[==========] 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:19:48.212934  1006 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.251.190:40117
I20260812 06:19:48.214033  1006 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:19:48.214665  1006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:48.221186  1014 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:48.221199  1019 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.221196  1006 server_base.cc:1061] running on GCE node
W20260812 06:19:48.221526  1021 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:19:48.222090  1006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:48.222208  1006 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:48.222254  1006 hybrid_clock.cc:648] HybridClock initialized: now 1786515588222252 us; error 0 us; skew 500 ppm
I20260812 06:19:48.224184  1006 webserver.cc:533] Webserver started at http://127.0.251.190:36521/ using document root <none> and password file <none>
I20260812 06:19:48.224798  1006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:48.224858  1006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:48.225139  1006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:48.226905  1006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/master-0-root/instance:
uuid: "9755629e06914f94ae988d830d65c1c9"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-gsp7"
I20260812 06:19:48.230472  1006 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:19:48.232540  1026 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.233595  1006 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:48.233718  1006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/master-0-root
uuid: "9755629e06914f94ae988d830d65c1c9"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-gsp7"
I20260812 06:19:48.233824  1006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:48.243321  1006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:48.243938  1006 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:19:48.244131  1006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:48.252166  1006 rpc_server.cc:307] RPC server started. Bound to: 127.0.251.190:40117
I20260812 06:19:48.252197  1099 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.251.190:40117 every 8 connection(s)
I20260812 06:19:48.254577  1103 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:48.260270  1103 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9: Bootstrap starting.
I20260812 06:19:48.262807  1103 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:48.263797  1103 log.cc:826] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:48.265620  1103 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9: No bootstrap required, opened a new log
I20260812 06:19:48.268540  1103 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9755629e06914f94ae988d830d65c1c9" member_type: VOTER }
I20260812 06:19:48.268719  1103 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:48.268818  1103 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9755629e06914f94ae988d830d65c1c9, State: Initialized, Role: FOLLOWER
I20260812 06:19:48.269459  1103 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [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: "9755629e06914f94ae988d830d65c1c9" member_type: VOTER }
I20260812 06:19:48.269726  1103 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:48.269800  1103 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:48.269976  1103 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:48.270865  1103 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9755629e06914f94ae988d830d65c1c9" member_type: VOTER }
I20260812 06:19:48.271344  1103 leader_election.cc:304] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [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: 9755629e06914f94ae988d830d65c1c9; no voters: 
I20260812 06:19:48.271688  1103 leader_election.cc:290] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:48.271835  1107 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:48.272107  1107 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 1 LEADER]: Becoming Leader. State: Replica: 9755629e06914f94ae988d830d65c1c9, State: Running, Role: LEADER
I20260812 06:19:48.272584  1107 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [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: "9755629e06914f94ae988d830d65c1c9" member_type: VOTER }
I20260812 06:19:48.272797  1103 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:48.274608  1109 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9755629e06914f94ae988d830d65c1c9. Latest consensus state: current_term: 1 leader_uuid: "9755629e06914f94ae988d830d65c1c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9755629e06914f94ae988d830d65c1c9" member_type: VOTER } }
I20260812 06:19:48.274664  1108 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9755629e06914f94ae988d830d65c1c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9755629e06914f94ae988d830d65c1c9" member_type: VOTER } }
I20260812 06:19:48.274737  1109 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:48.274755  1108 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:48.275079  1119 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:48.275520  1006 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:48.277258  1119 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:48.281610  1119 catalog_manager.cc:1383] Generated new cluster ID: f857f667c9404ebf9706a941e3856835
I20260812 06:19:48.281675  1119 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:48.298941  1119 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:48.299885  1119 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:48.308710  1119 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9: Generated new TSK 0
I20260812 06:19:48.309393  1119 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:48.340818  1006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:48.344170  1135 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.344285  1006 server_base.cc:1061] running on GCE node
W20260812 06:19:48.344347  1137 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:48.344153  1129 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:19:48.344712  1006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:48.344790  1006 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:48.344818  1006 hybrid_clock.cc:648] HybridClock initialized: now 1786515588344817 us; error 0 us; skew 500 ppm
I20260812 06:19:48.345809  1006 webserver.cc:533] Webserver started at http://127.0.251.129:41579/ using document root <none> and password file <none>
I20260812 06:19:48.346004  1006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:48.346081  1006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:48.346165  1006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:48.346597  1006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/instance:
uuid: "364455503f564e11be7bc91cf21c0abe"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-gsp7"
I20260812 06:19:48.348176  1006 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:48.349226  1146 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.349579  1006 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:48.349673  1006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root
uuid: "364455503f564e11be7bc91cf21c0abe"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-gsp7"
I20260812 06:19:48.349767  1006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:48.364889  1006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:48.365402  1006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:48.366034  1006 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:48.367012  1006 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:48.367069  1006 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.367146  1006 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:48.367187  1006 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.374341  1006 rpc_server.cc:307] RPC server started. Bound to: 127.0.251.129:34401
I20260812 06:19:48.374372  1241 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.251.129:34401 every 8 connection(s)
I20260812 06:19:48.384895  1242 heartbeater.cc:344] Connected to a master server at 127.0.251.190:40117
I20260812 06:19:48.385180  1242 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:48.385705  1242 heartbeater.cc:507] Master 127.0.251.190:40117 requested a full tablet report, sending...
I20260812 06:19:48.387128  1048 ts_manager.cc:194] Registered new tserver with Master: 364455503f564e11be7bc91cf21c0abe (127.0.251.129:34401)
I20260812 06:19:48.387423  1006 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012391862s
I20260812 06:19:48.388358  1048 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37520
I20260812 06:19:48.397367  1048 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37528:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:48.412909  1191 tablet_service.cc:1511] Processing CreateTablet for tablet 9612479314fc44f7a38e92fcb0c74720 (DEFAULT_TABLE table=heavy-update-compaction-test [id=44dc10e393b24686b11ba705c565c182]), partition=
I20260812 06:19:48.413393  1191 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9612479314fc44f7a38e92fcb0c74720. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:48.415752  1263 tablet_bootstrap.cc:492] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Bootstrap starting.
I20260812 06:19:48.416970  1263 tablet_bootstrap.cc:654] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:48.418401  1263 tablet_bootstrap.cc:492] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: No bootstrap required, opened a new log
I20260812 06:19:48.418519  1263 ts_tablet_manager.cc:1403] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:48.419026  1263 raft_consensus.cc:359] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "364455503f564e11be7bc91cf21c0abe" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 34401 } }
I20260812 06:19:48.419135  1263 raft_consensus.cc:385] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:48.419158  1263 raft_consensus.cc:740] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 364455503f564e11be7bc91cf21c0abe, State: Initialized, Role: FOLLOWER
I20260812 06:19:48.419324  1263 consensus_queue.cc:260] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [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: "364455503f564e11be7bc91cf21c0abe" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 34401 } }
I20260812 06:19:48.419407  1263 raft_consensus.cc:399] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:48.419454  1263 raft_consensus.cc:493] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:48.419519  1263 raft_consensus.cc:3060] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:48.420454  1263 raft_consensus.cc:515] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "364455503f564e11be7bc91cf21c0abe" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 34401 } }
I20260812 06:19:48.420606  1263 leader_election.cc:304] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [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: 364455503f564e11be7bc91cf21c0abe; no voters: 
I20260812 06:19:48.420836  1263 leader_election.cc:290] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:48.420970  1267 raft_consensus.cc:2804] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:48.421219  1267 raft_consensus.cc:697] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 1 LEADER]: Becoming Leader. State: Replica: 364455503f564e11be7bc91cf21c0abe, State: Running, Role: LEADER
I20260812 06:19:48.421299  1263 ts_tablet_manager.cc:1434] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:48.421433  1267 consensus_queue.cc:237] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [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: "364455503f564e11be7bc91cf21c0abe" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 34401 } }
I20260812 06:19:48.421571  1242 heartbeater.cc:499] Master 127.0.251.190:40117 was elected leader, sending a full tablet report...
I20260812 06:19:48.424691  1048 catalog_manager.cc:5719] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe reported cstate change: term changed from 0 to 1, leader changed from <none> to 364455503f564e11be7bc91cf21c0abe (127.0.251.129). New cstate: current_term: 1 leader_uuid: "364455503f564e11be7bc91cf21c0abe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "364455503f564e11be7bc91cf21c0abe" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 34401 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:48.496374  1006 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.029s	sys 0.003s
I20260812 06:19:48.625880  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushMRSOp(9612479314fc44f7a38e92fcb0c74720): perf score=18.062753
I20260812 06:19:48.818264  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushMRSOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.192s	user 0.163s	sys 0.020s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":223,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":935,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46134,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":103,"threads_started":1,"update_count":1500}
I20260812 06:19:48.819474  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling LogGCOp(9612479314fc44f7a38e92fcb0c74720): free 20743831 bytes of WAL
I20260812 06:19:48.819792  1154 log_reader.cc:385] T 9612479314fc44f7a38e92fcb0c74720: removed 2 log segments from log reader
I20260812 06:19:48.819873  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000001 (ops 1-6)
I20260812 06:19:48.819947  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000002 (ops 7-11)
I20260812 06:19:48.824163  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: LogGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:48.824512  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:48.844422  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.844959  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720): 16411393 bytes on disk
I20260812 06:19:48.845726  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.846179  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:49.003062  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.157s	user 0.108s	sys 0.040s 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":1114,"lbm_read_time_us":8836,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23171,"lbm_writes_lt_1ms":443,"mutex_wait_us":147,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":365,"threads_started":5,"update_count":2000}
I20260812 06:19:49.003703  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=11.118625
I20260812 06:19:49.033746  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.030s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":12788,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:49.034384  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:49.050644  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4834,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.051146  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:49.181620  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.130s	user 0.103s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":833,"lbm_read_time_us":7081,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26598,"lbm_writes_lt_1ms":443,"mutex_wait_us":1766,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.182389  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=11.118625
I20260812 06:19:49.216832  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.034s	user 0.010s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14194,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:49.217545  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:49.235138  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.017s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4802,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.235731  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:49.370850  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.135s	user 0.086s	sys 0.039s 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":237,"lbm_read_time_us":7184,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23219,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2000}
I20260812 06:19:49.371359  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=14.095187
I20260812 06:19:49.426632  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.055s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20293,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.427196  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:49.439468  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.439904  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:49.592777  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.153s	user 0.109s	sys 0.044s 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":347,"lbm_read_time_us":13239,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26009,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2500}
I20260812 06:19:49.593433  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:49.637915  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.044s	user 0.037s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18668,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.638474  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:49.662647  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.024s	user 0.011s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5780,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.663280  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:49.809453  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.146s	user 0.109s	sys 0.036s 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":719,"lbm_read_time_us":11523,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22929,"lbm_writes_lt_1ms":443,"mutex_wait_us":245,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.810206  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:49.855293  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.045s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19803,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.855831  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:49.867780  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.868242  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:49.984467  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.116s	user 0.085s	sys 0.028s 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":239,"lbm_read_time_us":7595,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23009,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:49.985149  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:50.023944  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16579,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.024526  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:50.041312  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.041795  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushMRSOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:50.074543  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushMRSOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1322,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2006,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:50.075605  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling LogGCOp(9612479314fc44f7a38e92fcb0c74720): free 112692416 bytes of WAL
I20260812 06:19:50.075874  1154 log_reader.cc:385] T 9612479314fc44f7a38e92fcb0c74720: removed 11 log segments from log reader
I20260812 06:19:50.075932  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000003 (ops 12-16)
I20260812 06:19:50.075961  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000004 (ops 17-21)
I20260812 06:19:50.075979  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000005 (ops 22-26)
I20260812 06:19:50.076041  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000006 (ops 27-31)
I20260812 06:19:50.076085  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000007 (ops 32-36)
I20260812 06:19:50.076131  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000008 (ops 37-41)
I20260812 06:19:50.076174  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000009 (ops 42-46)
I20260812 06:19:50.076241  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000010 (ops 47-51)
I20260812 06:19:50.076282  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000011 (ops 52-56)
I20260812 06:19:50.076323  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000012 (ops 57-61)
I20260812 06:19:50.076362  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000013 (ops 62-66)
I20260812 06:19:50.099306  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: LogGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:50.099738  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720): 473 bytes on disk
I20260812 06:19:50.100535  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:50.101038  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=6.157687
I20260812 06:19:50.126564  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.025s	user 0.013s	sys 0.011s Metrics: {"bytes_written":7630738,"delete_count":0,"lbm_write_time_us":10518,"lbm_writes_lt_1ms":189,"reinsert_count":0,"update_count":930}
I20260812 06:19:50.127161  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling LogGCOp(9612479314fc44f7a38e92fcb0c74720): free 12017927 bytes of WAL
I20260812 06:19:50.127704  1154 log_reader.cc:385] T 9612479314fc44f7a38e92fcb0c74720: removed 1 log segments from log reader
I20260812 06:19:50.127771  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000014 (ops 67-71)
I20260812 06:19:50.130669  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: LogGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:50.131081  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:50.312137  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.181s	user 0.131s	sys 0.037s Metrics: {"cfile_cache_miss":619,"cfile_cache_miss_bytes":28302880,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":263,"lbm_read_time_us":11039,"lbm_reads_lt_1ms":651,"lbm_write_time_us":37637,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":627,"mutex_wait_us":28,"peak_mem_usage":72887214,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":82,"threads_started":1,"update_count":2930}
I20260812 06:19:50.312784  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=15.087375
I20260812 06:19:50.360901  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.048s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16984247,"delete_count":0,"lbm_write_time_us":19947,"lbm_writes_lt_1ms":417,"reinsert_count":0,"update_count":2070}
I20260812 06:19:50.361415  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:50.377450  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.378002  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:50.530548  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.152s	user 0.121s	sys 0.030s Metrics: {"cfile_cache_miss":546,"cfile_cache_miss_bytes":25349033,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":12286,"lbm_reads_lt_1ms":586,"lbm_write_time_us":28755,"lbm_writes_lt_1ms":557,"mutex_wait_us":50,"peak_mem_usage":64730774,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2570}
I20260812 06:19:50.531263  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=11.118625
I20260812 06:19:50.570336  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.039s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16411,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.570951  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:50.589042  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.018s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5387,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.589643  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:50.725374  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.136s	user 0.096s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":10055,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24365,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:50.726481  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:50.769973  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.043s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.770701  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:50.788187  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.788736  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:50.936177  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.147s	user 0.095s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":309,"lbm_read_time_us":10956,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24153,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:50.936771  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:50.986997  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.050s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17225,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.987466  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:50.998701  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.999361  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:51.121796  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.122s	user 0.096s	sys 0.026s 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":1019,"lbm_read_time_us":9576,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23030,"lbm_writes_lt_1ms":443,"mutex_wait_us":342,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:19:51.122316  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:51.162047  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.040s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.162551  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:51.178076  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.178736  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:51.299471  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.120s	user 0.102s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":9029,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21753,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:51.301195  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:51.347149  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.046s	user 0.019s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16094,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.347744  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:51.358618  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.359086  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:51.503561  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.144s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":10335,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23807,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:51.504902  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=10.126437
I20260812 06:19:51.544780  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.040s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":18387,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.545265  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:51.557600  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.558109  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushMRSOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:51.588626  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushMRSOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1273,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1379,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:51.589396  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling LogGCOp(9612479314fc44f7a38e92fcb0c74720): free 124257262 bytes of WAL
I20260812 06:19:51.589668  1154 log_reader.cc:385] T 9612479314fc44f7a38e92fcb0c74720: removed 12 log segments from log reader
I20260812 06:19:51.589716  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000015 (ops 72-76)
I20260812 06:19:51.589745  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000016 (ops 77-81)
I20260812 06:19:51.589766  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000017 (ops 82-86)
I20260812 06:19:51.589823  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000018 (ops 87-91)
I20260812 06:19:51.589865  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000019 (ops 92-96)
I20260812 06:19:51.589896  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000020 (ops 97-101)
I20260812 06:19:51.589931  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000021 (ops 102-106)
I20260812 06:19:51.589959  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000022 (ops 107-111)
I20260812 06:19:51.590008  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000023 (ops 112-116)
I20260812 06:19:51.590051  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000024 (ops 117-120)
I20260812 06:19:51.590082  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000025 (ops 121-125)
I20260812 06:19:51.590116  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000026 (ops 126-130)
I20260812 06:19:51.617592  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: LogGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:51.618166  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720): 472 bytes on disk
I20260812 06:19:51.618724  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.619251  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=6.157687
I20260812 06:19:51.647408  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.028s	user 0.009s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9548,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:51.647887  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:51.828042  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.180s	user 0.115s	sys 0.065s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877224,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":230,"lbm_read_time_us":14471,"lbm_reads_lt_1ms":665,"lbm_write_time_us":30665,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:19:51.828831  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=14.095187
I20260812 06:19:51.888089  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.059s	user 0.025s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21805,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.888720  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:51.900487  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.901015  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:52.071401  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.170s	user 0.110s	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":362,"lbm_read_time_us":11867,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27315,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.072074  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=14.095187
I20260812 06:19:52.119755  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.047s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20201,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.120338  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:52.147408  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.027s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.147979  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:52.162905  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.015s	user 0.011s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.163494  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:52.374583  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.211s	user 0.150s	sys 0.061s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":996,"lbm_read_time_us":15387,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37266,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":3000}
I20260812 06:19:52.375376  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=14.095187
I20260812 06:19:52.431608  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.056s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20797,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.432196  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:52.445849  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.446352  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:52.615226  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.169s	user 0.113s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":460,"lbm_read_time_us":11774,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28727,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:52.616003  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=14.095187
I20260812 06:19:52.676030  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.060s	user 0.025s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21715,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.676684  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:52.687609  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.688126  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:52.884121  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.196s	user 0.143s	sys 0.040s 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":198,"lbm_read_time_us":15730,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30012,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.884883  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=14.095187
I20260812 06:19:52.934412  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.049s	user 0.041s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21786,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.935222  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:52.954728  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.019s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6646,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.960624  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushMRSOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:52.994225  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushMRSOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1486,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1579,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:52.994971  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling LogGCOp(9612479314fc44f7a38e92fcb0c74720): free 112692610 bytes of WAL
I20260812 06:19:52.995240  1154 log_reader.cc:385] T 9612479314fc44f7a38e92fcb0c74720: removed 11 log segments from log reader
I20260812 06:19:52.995287  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000027 (ops 131-135)
I20260812 06:19:52.995316  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000028 (ops 136-140)
I20260812 06:19:52.995378  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000029 (ops 141-145)
I20260812 06:19:52.995427  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000030 (ops 146-150)
I20260812 06:19:52.995471  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000031 (ops 151-155)
I20260812 06:19:52.995522  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000032 (ops 156-160)
I20260812 06:19:52.995561  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000033 (ops 161-165)
I20260812 06:19:52.995602  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000034 (ops 166-170)
I20260812 06:19:52.995640  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000035 (ops 171-175)
I20260812 06:19:52.995678  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000036 (ops 176-180)
I20260812 06:19:52.995720  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000037 (ops 181-185)
I20260812 06:19:53.019491  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: LogGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.024s	user 0.003s	sys 0.019s Metrics: {}
I20260812 06:19:53.019944  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720): 462 bytes on disk
I20260812 06:19:53.020422  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: UndoDeltaBlockGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.021049  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=3.181125
I20260812 06:19:53.042114  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.021s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6918,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:53.042577  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:53.052371  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3517,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.052825  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling LogGCOp(9612479314fc44f7a38e92fcb0c74720): free 12017952 bytes of WAL
I20260812 06:19:53.053047  1154 log_reader.cc:385] T 9612479314fc44f7a38e92fcb0c74720: removed 1 log segments from log reader
I20260812 06:19:53.053094  1154 log.cc:1079] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/9612479314fc44f7a38e92fcb0c74720/wal-000000038 (ops 186-190)
I20260812 06:19:53.056221  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: LogGCOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:53.056643  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:53.277770  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.221s	user 0.142s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1625,"lbm_read_time_us":15932,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37013,"lbm_writes_lt_1ms":743,"mutex_wait_us":1252,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17920,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:19:53.278764  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=18.063937
I20260812 06:19:53.355540  1006 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.859s	user 1.803s	sys 0.151s
I20260812 06:19:53.359345  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.080s	user 0.044s	sys 0.021s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29730,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:53.359827  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720): perf score=2.188937
I20260812 06:19:53.376614  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: FlushDeltaMemStoresOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":500}
I20260812 06:19:53.377274  1244 maintenance_manager.cc:419] P 364455503f564e11be7bc91cf21c0abe: Scheduling MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720): perf score=1.000000
I20260812 06:19:53.461843  1006 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.106s	user 0.004s	sys 0.000s
I20260812 06:19:53.462567  1006 tablet_server.cc:179] TabletServer@127.0.251.129:0 shutting down...
I20260812 06:19:53.555416  1154 maintenance_manager.cc:643] P 364455503f564e11be7bc91cf21c0abe: MajorDeltaCompactionOp(9612479314fc44f7a38e92fcb0c74720) complete. Timing: real 0.178s	user 0.126s	sys 0.050s Metrics: {"cfile_cache_hit":278,"cfile_cache_hit_bytes":11366729,"cfile_cache_miss":354,"cfile_cache_miss_bytes":17510374,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":999,"lbm_read_time_us":10665,"lbm_reads_lt_1ms":386,"lbm_write_time_us":32974,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":74112,"update_count":3000}
I20260812 06:19:53.556241  1006 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:53.556664  1006 tablet_replica.cc:333] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe: stopping tablet replica
I20260812 06:19:53.556944  1006 raft_consensus.cc:2243] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.557197  1006 raft_consensus.cc:2272] T 9612479314fc44f7a38e92fcb0c74720 P 364455503f564e11be7bc91cf21c0abe [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.573310  1006 tablet_server.cc:196] TabletServer@127.0.251.129:0 shutdown complete.
I20260812 06:19:53.608219  1006 master.cc:562] Master@127.0.251.190:40117 shutting down...
I20260812 06:19:53.612000  1006 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.612221  1006 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.612326  1006 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9755629e06914f94ae988d830d65c1c9: stopping tablet replica
I20260812 06:19:53.624766  1006 master.cc:584] Master@127.0.251.190:40117 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5500 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:53.725378  1006 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.251.190:43991
I20260812 06:19:53.725903  1006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:53.728348  1301 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:19:53.728355  1006 server_base.cc:1061] running on GCE node
W20260812 06:19:53.728462  1294 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:53.728355  1295 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:53.728734  1006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:53.728808  1006 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:53.728835  1006 hybrid_clock.cc:648] HybridClock initialized: now 1786515593728834 us; error 0 us; skew 500 ppm
I20260812 06:19:53.729794  1006 webserver.cc:533] Webserver started at http://127.0.251.190:34501/ using document root <none> and password file <none>
I20260812 06:19:53.729985  1006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:53.730077  1006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:53.730163  1006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:53.730619  1006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/master-0-root/instance:
uuid: "c09562cde5784d95922b49b9627a7fd6"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-gsp7"
I20260812 06:19:53.732188  1006 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:53.733142  1308 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:53.733399  1006 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:53.733521  1006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/master-0-root
uuid: "c09562cde5784d95922b49b9627a7fd6"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-gsp7"
I20260812 06:19:53.733598  1006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:53.740406  1006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:53.740829  1006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:53.745304  1006 rpc_server.cc:307] RPC server started. Bound to: 127.0.251.190:43991
I20260812 06:19:53.747153  1385 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.251.190:43991 every 8 connection(s)
I20260812 06:19:53.752086  1386 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:53.754383  1386 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6: Bootstrap starting.
I20260812 06:19:53.755251  1386 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:53.756541  1386 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6: No bootstrap required, opened a new log
I20260812 06:19:53.757006  1386 raft_consensus.cc:359] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c09562cde5784d95922b49b9627a7fd6" member_type: VOTER }
I20260812 06:19:53.757100  1386 raft_consensus.cc:385] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:53.757123  1386 raft_consensus.cc:740] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c09562cde5784d95922b49b9627a7fd6, State: Initialized, Role: FOLLOWER
I20260812 06:19:53.757340  1386 consensus_queue.cc:260] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [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: "c09562cde5784d95922b49b9627a7fd6" member_type: VOTER }
I20260812 06:19:53.757416  1386 raft_consensus.cc:399] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:53.757498  1386 raft_consensus.cc:493] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:53.757582  1386 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:53.758353  1386 raft_consensus.cc:515] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c09562cde5784d95922b49b9627a7fd6" member_type: VOTER }
I20260812 06:19:53.758503  1386 leader_election.cc:304] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [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: c09562cde5784d95922b49b9627a7fd6; no voters: 
I20260812 06:19:53.758754  1386 leader_election.cc:290] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:53.758898  1391 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:53.759140  1391 raft_consensus.cc:697] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 1 LEADER]: Becoming Leader. State: Replica: c09562cde5784d95922b49b9627a7fd6, State: Running, Role: LEADER
I20260812 06:19:53.759243  1386 sys_catalog.cc:565] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:53.759330  1391 consensus_queue.cc:237] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [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: "c09562cde5784d95922b49b9627a7fd6" member_type: VOTER }
I20260812 06:19:53.759816  1392 sys_catalog.cc:455] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c09562cde5784d95922b49b9627a7fd6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c09562cde5784d95922b49b9627a7fd6" member_type: VOTER } }
I20260812 06:19:53.759851  1393 sys_catalog.cc:455] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c09562cde5784d95922b49b9627a7fd6. Latest consensus state: current_term: 1 leader_uuid: "c09562cde5784d95922b49b9627a7fd6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c09562cde5784d95922b49b9627a7fd6" member_type: VOTER } }
I20260812 06:19:53.759913  1392 sys_catalog.cc:458] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:53.759950  1393 sys_catalog.cc:458] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:53.760501  1397 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:53.761518  1397 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:53.761741  1006 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:53.763305  1397 catalog_manager.cc:1383] Generated new cluster ID: cfaed06f86c44bb1bc16fbb9db3dcd82
I20260812 06:19:53.763365  1397 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:53.769716  1397 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:53.770267  1397 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:53.775097  1397 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6: Generated new TSK 0
I20260812 06:19:53.775259  1397 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:53.777872  1006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:53.779973  1413 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:19:53.780026  1006 server_base.cc:1061] running on GCE node
W20260812 06:19:53.780046  1416 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:53.780025  1414 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:53.780504  1006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:53.780576  1006 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:53.780598  1006 hybrid_clock.cc:648] HybridClock initialized: now 1786515593780598 us; error 0 us; skew 500 ppm
I20260812 06:19:53.781461  1006 webserver.cc:533] Webserver started at http://127.0.251.129:41211/ using document root <none> and password file <none>
I20260812 06:19:53.781714  1006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:53.781783  1006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:53.781867  1006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:53.782281  1006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/instance:
uuid: "bc0ddcba07b1439bb4ff3a250263f166"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-gsp7"
I20260812 06:19:53.783819  1006 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:53.784766  1423 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:53.785077  1006 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:53.785142  1006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root
uuid: "bc0ddcba07b1439bb4ff3a250263f166"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-gsp7"
I20260812 06:19:53.785202  1006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:53.841969  1006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:53.842412  1006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:53.842705  1006 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:53.843256  1006 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:53.843302  1006 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:53.843370  1006 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:53.843410  1006 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:53.847618  1006 rpc_server.cc:307] RPC server started. Bound to: 127.0.251.129:35599
I20260812 06:19:53.847699  1520 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.251.129:35599 every 8 connection(s)
I20260812 06:19:53.855942  1526 heartbeater.cc:344] Connected to a master server at 127.0.251.190:43991
I20260812 06:19:53.856069  1526 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:53.856273  1526 heartbeater.cc:507] Master 127.0.251.190:43991 requested a full tablet report, sending...
I20260812 06:19:53.856910  1332 ts_manager.cc:194] Registered new tserver with Master: bc0ddcba07b1439bb4ff3a250263f166 (127.0.251.129:35599)
I20260812 06:19:53.857059  1006 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008958177s
I20260812 06:19:53.857828  1332 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50664
I20260812 06:19:53.864457  1332 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50678:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:53.873536  1465 tablet_service.cc:1511] Processing CreateTablet for tablet 0b208cc8378548898ec13841301d1ca1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=67615a0e851c470fbb0363f66cb34bea]), partition=
I20260812 06:19:53.873811  1465 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0b208cc8378548898ec13841301d1ca1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:53.876025  1547 tablet_bootstrap.cc:492] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Bootstrap starting.
I20260812 06:19:53.876876  1547 tablet_bootstrap.cc:654] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:53.877948  1547 tablet_bootstrap.cc:492] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: No bootstrap required, opened a new log
I20260812 06:19:53.878065  1547 ts_tablet_manager.cc:1403] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:53.878489  1547 raft_consensus.cc:359] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc0ddcba07b1439bb4ff3a250263f166" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 35599 } }
I20260812 06:19:53.878628  1547 raft_consensus.cc:385] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:53.878674  1547 raft_consensus.cc:740] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bc0ddcba07b1439bb4ff3a250263f166, State: Initialized, Role: FOLLOWER
I20260812 06:19:53.878859  1547 consensus_queue.cc:260] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [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: "bc0ddcba07b1439bb4ff3a250263f166" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 35599 } }
I20260812 06:19:53.878988  1547 raft_consensus.cc:399] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:53.879036  1547 raft_consensus.cc:493] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:53.879089  1547 raft_consensus.cc:3060] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:53.879870  1547 raft_consensus.cc:515] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc0ddcba07b1439bb4ff3a250263f166" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 35599 } }
I20260812 06:19:53.879997  1547 leader_election.cc:304] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [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: bc0ddcba07b1439bb4ff3a250263f166; no voters: 
I20260812 06:19:53.880162  1547 leader_election.cc:290] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:53.880303  1550 raft_consensus.cc:2804] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:53.880494  1547 ts_tablet_manager.cc:1434] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:53.880525  1526 heartbeater.cc:499] Master 127.0.251.190:43991 was elected leader, sending a full tablet report...
I20260812 06:19:53.880561  1550 raft_consensus.cc:697] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 1 LEADER]: Becoming Leader. State: Replica: bc0ddcba07b1439bb4ff3a250263f166, State: Running, Role: LEADER
I20260812 06:19:53.880745  1550 consensus_queue.cc:237] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [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: "bc0ddcba07b1439bb4ff3a250263f166" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 35599 } }
I20260812 06:19:53.882038  1332 catalog_manager.cc:5719] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 reported cstate change: term changed from 0 to 1, leader changed from <none> to bc0ddcba07b1439bb4ff3a250263f166 (127.0.251.129). New cstate: current_term: 1 leader_uuid: "bc0ddcba07b1439bb4ff3a250263f166" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc0ddcba07b1439bb4ff3a250263f166" member_type: VOTER last_known_addr { host: "127.0.251.129" port: 35599 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:53.941897  1006 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.019s	sys 0.004s
I20260812 06:19:54.098627  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushMRSOp(0b208cc8378548898ec13841301d1ca1): perf score=19.054940
I20260812 06:19:54.248510  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushMRSOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.150s	user 0.111s	sys 0.036s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":817,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35657,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:54.249228  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling LogGCOp(0b208cc8378548898ec13841301d1ca1): free 20743880 bytes of WAL
I20260812 06:19:54.249524  1432 log_reader.cc:385] T 0b208cc8378548898ec13841301d1ca1: removed 2 log segments from log reader
I20260812 06:19:54.249585  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000001 (ops 1-6)
I20260812 06:19:54.249637  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000002 (ops 7-11)
I20260812 06:19:54.253873  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: LogGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.004s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:54.254247  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:54.270090  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.271097  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:54.422927  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.152s	user 0.111s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":589,"lbm_read_time_us":9802,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23347,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":306,"threads_started":5,"update_count":2000}
I20260812 06:19:54.423521  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1): 16411393 bytes on disk
I20260812 06:19:54.423909  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.424320  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=11.118625
I20260812 06:19:54.464676  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.040s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18044,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:54.465166  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:54.492115  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.027s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3811,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.492700  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:54.509104  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.509795  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:54.692240  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.182s	user 0.080s	sys 0.096s 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":275,"lbm_read_time_us":13445,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26568,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:54.692906  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:54.746074  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.053s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.746567  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:54.775372  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.029s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.775880  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:54.942682  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.167s	user 0.097s	sys 0.068s 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":190,"lbm_read_time_us":11861,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25841,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:54.943392  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:54.992957  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20768,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.993397  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:55.019234  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.026s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5350,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.019757  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:55.044946  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.025s	user 0.012s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.045637  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:55.240226  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.194s	user 0.113s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":692,"lbm_read_time_us":13921,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29897,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":3000}
I20260812 06:19:55.240907  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:55.293239  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.052s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23084,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.293843  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:55.316804  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.023s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5287,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.317534  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:55.518693  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.201s	user 0.128s	sys 0.066s 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":464,"lbm_read_time_us":14330,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30700,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":57856,"update_count":2500}
I20260812 06:19:55.519296  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:55.569079  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.050s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18633,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.569747  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:55.581329  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.582134  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushMRSOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:55.619091  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushMRSOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.037s	user 0.029s	sys 0.002s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1157,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2485,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:55.619805  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling LogGCOp(0b208cc8378548898ec13841301d1ca1): free 121006430 bytes of WAL
I20260812 06:19:55.620072  1432 log_reader.cc:385] T 0b208cc8378548898ec13841301d1ca1: removed 12 log segments from log reader
I20260812 06:19:55.620139  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000003 (ops 12-16)
I20260812 06:19:55.620194  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000004 (ops 17-21)
I20260812 06:19:55.620246  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000005 (ops 22-26)
I20260812 06:19:55.620286  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000006 (ops 27-31)
I20260812 06:19:55.620325  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000007 (ops 32-36)
I20260812 06:19:55.620362  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000008 (ops 37-41)
I20260812 06:19:55.620409  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000009 (ops 42-46)
I20260812 06:19:55.620441  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000010 (ops 47-51)
I20260812 06:19:55.620484  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000011 (ops 52-56)
I20260812 06:19:55.620520  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000012 (ops 57-60)
I20260812 06:19:55.620559  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000013 (ops 61-65)
I20260812 06:19:55.620596  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000014 (ops 66-70)
I20260812 06:19:55.648381  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: LogGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:55.648829  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=3.181125
I20260812 06:19:55.673333  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.024s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7218,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:55.673898  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1): 473 bytes on disk
I20260812 06:19:55.674335  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:55.674815  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:55.686043  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.011s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3872,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.686693  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:55.938448  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.252s	user 0.144s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":693,"lbm_read_time_us":14475,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39928,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:19:55.941218  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=18.063937
I20260812 06:19:55.998787  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.057s	user 0.033s	sys 0.019s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":24454,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:55.999264  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:56.170256  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.171s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774575,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1204,"lbm_read_time_us":12143,"lbm_reads_lt_1ms":563,"lbm_write_time_us":28217,"lbm_writes_lt_1ms":543,"mutex_wait_us":603,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":86528,"update_count":2500}
I20260812 06:19:56.171074  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=15.087375
I20260812 06:19:56.221271  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.050s	user 0.015s	sys 0.031s Metrics: {"bytes_written":16820148,"delete_count":0,"lbm_write_time_us":18142,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:56.221824  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:56.238756  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3859,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.239197  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:56.250005  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4174,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.250574  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:56.466531  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.216s	user 0.124s	sys 0.091s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877212,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1255,"lbm_read_time_us":14401,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34972,"lbm_writes_lt_1ms":643,"mutex_wait_us":378,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29312,"update_count":3000}
I20260812 06:19:56.467092  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:56.513128  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.046s	user 0.018s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20088,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.513763  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:56.531580  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.532119  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:56.701458  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.169s	user 0.109s	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":241,"lbm_read_time_us":10730,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28186,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2500}
I20260812 06:19:56.702018  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:56.767289  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.065s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23458,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.767879  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:56.785245  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.786077  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:56.973631  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.187s	user 0.121s	sys 0.051s 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":681,"lbm_read_time_us":12193,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31971,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:56.974328  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:57.033898  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.059s	user 0.043s	sys 0.015s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21988,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.034459  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:57.045876  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.011s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.046386  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushMRSOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:57.091954  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushMRSOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.045s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1241,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2216,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:57.092592  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling LogGCOp(0b208cc8378548898ec13841301d1ca1): free 115943124 bytes of WAL
I20260812 06:19:57.092818  1432 log_reader.cc:385] T 0b208cc8378548898ec13841301d1ca1: removed 11 log segments from log reader
I20260812 06:19:57.092877  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000015 (ops 71-75)
I20260812 06:19:57.092936  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000016 (ops 76-80)
I20260812 06:19:57.092988  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000017 (ops 81-85)
I20260812 06:19:57.093031  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000018 (ops 86-90)
I20260812 06:19:57.093070  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000019 (ops 91-95)
I20260812 06:19:57.093109  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000020 (ops 96-100)
I20260812 06:19:57.093148  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000021 (ops 101-105)
I20260812 06:19:57.093189  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000022 (ops 106-110)
I20260812 06:19:57.093228  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000023 (ops 111-115)
I20260812 06:19:57.093267  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000024 (ops 116-120)
I20260812 06:19:57.093307  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000025 (ops 121-125)
I20260812 06:19:57.118172  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: LogGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:57.118602  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1): 447 bytes on disk
I20260812 06:19:57.119239  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.119769  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=3.181125
I20260812 06:19:57.142256  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.022s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7086,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:57.142738  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:57.152741  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:57.153239  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:57.385589  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.232s	user 0.154s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":441,"lbm_read_time_us":18493,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37469,"lbm_writes_lt_1ms":743,"mutex_wait_us":1,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:19:57.386209  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=18.063937
I20260812 06:19:57.446139  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.060s	user 0.026s	sys 0.032s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26194,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:57.446671  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:57.464016  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.464689  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:57.624796  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.160s	user 0.116s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":10676,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34027,"lbm_writes_lt_1ms":643,"mutex_wait_us":70,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:57.625527  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:57.679878  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.054s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24391,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.680439  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:57.698738  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.699326  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:57.863308  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.164s	user 0.100s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1210,"lbm_read_time_us":12155,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30817,"lbm_writes_lt_1ms":543,"mutex_wait_us":456,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2500}
I20260812 06:19:57.863982  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:57.919102  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.055s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24122,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.919602  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:58.076685  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.157s	user 0.074s	sys 0.071s 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":991,"lbm_read_time_us":10614,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21781,"lbm_writes_lt_1ms":443,"mutex_wait_us":368,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":81024,"update_count":2000}
I20260812 06:19:58.077193  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:58.130772  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.053s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22294,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.131390  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:58.143824  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.144431  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:58.317117  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.172s	user 0.107s	sys 0.063s 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":403,"lbm_read_time_us":11280,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28031,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:19:58.317883  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:58.364718  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.047s	user 0.026s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20717,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.365320  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:58.381778  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.016s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.382266  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:58.548341  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.166s	user 0.141s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":10693,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31888,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:19:58.548979  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=11.118625
I20260812 06:19:58.586623  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.037s	user 0.036s	sys 0.000s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15907,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:58.587205  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:58.602085  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5234,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":450}
I20260812 06:19:58.602662  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushMRSOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:58.641628  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushMRSOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.039s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":114,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1281,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1820,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:58.642767  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1): 493 bytes on disk
I20260812 06:19:58.643296  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: UndoDeltaBlockGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.643895  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=3.181125
I20260812 06:19:58.662194  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.018s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7224,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:58.662670  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling LogGCOp(0b208cc8378548898ec13841301d1ca1): free 132571629 bytes of WAL
I20260812 06:19:58.662897  1432 log_reader.cc:385] T 0b208cc8378548898ec13841301d1ca1: removed 13 log segments from log reader
I20260812 06:19:58.662940  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000026 (ops 126-130)
I20260812 06:19:58.662968  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000027 (ops 131-134)
I20260812 06:19:58.663029  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000028 (ops 135-139)
I20260812 06:19:58.663069  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000029 (ops 140-144)
I20260812 06:19:58.663115  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000030 (ops 145-149)
I20260812 06:19:58.663169  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000031 (ops 150-154)
I20260812 06:19:58.663223  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000032 (ops 155-159)
I20260812 06:19:58.663259  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000033 (ops 160-164)
I20260812 06:19:58.663298  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000034 (ops 165-168)
I20260812 06:19:58.663342  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000035 (ops 169-173)
I20260812 06:19:58.663384  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000036 (ops 174-178)
I20260812 06:19:58.663424  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000037 (ops 179-183)
I20260812 06:19:58.663461  1432 log.cc:1079] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: Deleting log segment in path: /tmp/dist-test-taskp0eueP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515588202047-1006-0/minicluster-data/ts-0-root/wals/0b208cc8378548898ec13841301d1ca1/wal-000000038 (ops 184-188)
I20260812 06:19:58.693120  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: LogGCOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:58.693639  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=3.181125
I20260812 06:19:58.715684  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.022s	user 0.001s	sys 0.018s Metrics: {"bytes_written":4553926,"delete_count":0,"lbm_write_time_us":4806,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:19:58.716260  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=2.188937
I20260812 06:19:58.730173  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":5195,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:58.730649  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:58.939749  1006 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.998s	user 1.798s	sys 0.230s
I20260812 06:19:58.963836  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.233s	user 0.148s	sys 0.083s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979840,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":15910,"lbm_reads_lt_1ms":771,"lbm_write_time_us":41863,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:19:58.964387  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1): perf score=14.095187
I20260812 06:19:58.997704  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: FlushDeltaMemStoresOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.033s	user 0.020s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16385,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:19:58.998375  1528 maintenance_manager.cc:419] P bc0ddcba07b1439bb4ff3a250263f166: Scheduling MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1): perf score=1.000000
I20260812 06:19:59.033319  1006 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.001s	sys 0.004s
I20260812 06:19:59.034063  1006 tablet_server.cc:179] TabletServer@127.0.251.129:0 shutting down...
I20260812 06:19:59.136026  1432 maintenance_manager.cc:643] P bc0ddcba07b1439bb4ff3a250263f166: MajorDeltaCompactionOp(0b208cc8378548898ec13841301d1ca1) complete. Timing: real 0.137s	user 0.071s	sys 0.066s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":344,"lbm_read_time_us":10004,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23894,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:19:59.137020  1006 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:59.137254  1006 tablet_replica.cc:333] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166: stopping tablet replica
I20260812 06:19:59.137383  1006 raft_consensus.cc:2243] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.137595  1006 raft_consensus.cc:2272] T 0b208cc8378548898ec13841301d1ca1 P bc0ddcba07b1439bb4ff3a250263f166 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.151691  1006 tablet_server.cc:196] TabletServer@127.0.251.129:0 shutdown complete.
I20260812 06:19:59.175407  1006 master.cc:562] Master@127.0.251.190:43991 shutting down...
I20260812 06:19:59.178828  1006 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.179054  1006 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.179139  1006 tablet_replica.cc:333] T 00000000000000000000000000000000 P c09562cde5784d95922b49b9627a7fd6: stopping tablet replica
I20260812 06:19:59.191563  1006 master.cc:584] Master@127.0.251.190:43991 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5567 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11068 ms total)

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