[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:11.287475 29925 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.57.126:37555
I20260812 06:17:11.288556 29925 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:11.289175 29925 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:11.297138 29935 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.297138 29932 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.297420 29933 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:11.297484 29925 server_base.cc:1061] running on GCE node
I20260812 06:17:11.298195 29925 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:11.298352 29925 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:11.298421 29925 hybrid_clock.cc:648] HybridClock initialized: now 1786515431298417 us; error 0 us; skew 500 ppm
I20260812 06:17:11.300614 29925 webserver.cc:533] Webserver started at http://127.29.57.126:46429/ using document root <none> and password file <none>
I20260812 06:17:11.301244 29925 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:11.301337 29925 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:11.301671 29925 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:11.303622 29925 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/master-0-root/instance:
uuid: "82b47f783d1246a88f9136ae2b713016"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-w206"
I20260812 06:17:11.307721 29925 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:11.310287 29941 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.311653 29925 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:11.311826 29925 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/master-0-root
uuid: "82b47f783d1246a88f9136ae2b713016"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-w206"
I20260812 06:17:11.311955 29925 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:11.323289 29925 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:11.324057 29925 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:11.324263 29925 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:11.333060 30002 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.57.126:37555 every 8 connection(s)
I20260812 06:17:11.333072 29925 rpc_server.cc:307] RPC server started. Bound to: 127.29.57.126:37555
I20260812 06:17:11.335824 30003 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:11.342335 30003 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016: Bootstrap starting.
I20260812 06:17:11.344940 30003 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.345955 30003 log.cc:826] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:11.348021 30003 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016: No bootstrap required, opened a new log
I20260812 06:17:11.351152 30003 raft_consensus.cc:359] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82b47f783d1246a88f9136ae2b713016" member_type: VOTER }
I20260812 06:17:11.351384 30003 raft_consensus.cc:385] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.351444 30003 raft_consensus.cc:740] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 82b47f783d1246a88f9136ae2b713016, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.352088 30003 consensus_queue.cc:260] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [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: "82b47f783d1246a88f9136ae2b713016" member_type: VOTER }
I20260812 06:17:11.352243 30003 raft_consensus.cc:399] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.352289 30003 raft_consensus.cc:493] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.352397 30003 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.353298 30003 raft_consensus.cc:515] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82b47f783d1246a88f9136ae2b713016" member_type: VOTER }
I20260812 06:17:11.353771 30003 leader_election.cc:304] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [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: 82b47f783d1246a88f9136ae2b713016; no voters: 
I20260812 06:17:11.354087 30003 leader_election.cc:290] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.354247 30007 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.354559 30007 raft_consensus.cc:697] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 1 LEADER]: Becoming Leader. State: Replica: 82b47f783d1246a88f9136ae2b713016, State: Running, Role: LEADER
I20260812 06:17:11.355096 30007 consensus_queue.cc:237] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [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: "82b47f783d1246a88f9136ae2b713016" member_type: VOTER }
I20260812 06:17:11.355485 30003 sys_catalog.cc:565] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:11.357309 30008 sys_catalog.cc:455] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 82b47f783d1246a88f9136ae2b713016. Latest consensus state: current_term: 1 leader_uuid: "82b47f783d1246a88f9136ae2b713016" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82b47f783d1246a88f9136ae2b713016" member_type: VOTER } }
I20260812 06:17:11.357342 30009 sys_catalog.cc:455] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "82b47f783d1246a88f9136ae2b713016" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82b47f783d1246a88f9136ae2b713016" member_type: VOTER } }
I20260812 06:17:11.357476 30009 sys_catalog.cc:458] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.357475 30008 sys_catalog.cc:458] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.357954 30022 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:11.358002 29925 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:11.360549 30022 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:11.366370 30022 catalog_manager.cc:1383] Generated new cluster ID: b275ce60eb4d489483ebc4d333226cae
I20260812 06:17:11.366572 30022 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:11.380342 30022 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:11.381315 30022 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:11.391081 30022 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016: Generated new TSK 0
I20260812 06:17:11.391880 30022 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:11.423115 29925 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:11.426115 30028 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.426115 30031 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.426265 30029 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:11.426605 29925 server_base.cc:1061] running on GCE node
I20260812 06:17:11.426844 29925 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:11.426894 29925 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:11.426918 29925 hybrid_clock.cc:648] HybridClock initialized: now 1786515431426918 us; error 0 us; skew 500 ppm
I20260812 06:17:11.427973 29925 webserver.cc:533] Webserver started at http://127.29.57.65:41785/ using document root <none> and password file <none>
I20260812 06:17:11.428155 29925 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:11.428220 29925 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:11.428298 29925 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:11.428777 29925 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/instance:
uuid: "3ac97c618348459ebe1198ead17338e6"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-w206"
I20260812 06:17:11.430764 29925 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:11.432030 30037 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.432360 29925 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:11.432446 29925 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root
uuid: "3ac97c618348459ebe1198ead17338e6"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-w206"
I20260812 06:17:11.432523 29925 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:11.463244 29925 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:11.463840 29925 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:11.464429 29925 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:11.465480 29925 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:11.465551 29925 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.465613 29925 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:11.465637 29925 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.473138 29925 rpc_server.cc:307] RPC server started. Bound to: 127.29.57.65:43379
I20260812 06:17:11.473203 30109 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.57.65:43379 every 8 connection(s)
I20260812 06:17:11.484277 30110 heartbeater.cc:344] Connected to a master server at 127.29.57.126:37555
I20260812 06:17:11.484632 30110 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:11.485149 30110 heartbeater.cc:507] Master 127.29.57.126:37555 requested a full tablet report, sending...
I20260812 06:17:11.486673 29959 ts_manager.cc:194] Registered new tserver with Master: 3ac97c618348459ebe1198ead17338e6 (127.29.57.65:43379)
I20260812 06:17:11.487394 29925 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013501913s
I20260812 06:17:11.488034 29959 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59212
I20260812 06:17:11.500324 29959 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59228:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:11.516451 30070 tablet_service.cc:1511] Processing CreateTablet for tablet c2c427f4bd894d3989a60bb5c48eade4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f98875c185eb4f728df9af2be797a345]), partition=
I20260812 06:17:11.517060 30070 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c2c427f4bd894d3989a60bb5c48eade4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:11.519627 30124 tablet_bootstrap.cc:492] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Bootstrap starting.
I20260812 06:17:11.521426 30124 tablet_bootstrap.cc:654] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.522876 30124 tablet_bootstrap.cc:492] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: No bootstrap required, opened a new log
I20260812 06:17:11.523080 30124 ts_tablet_manager.cc:1403] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:11.523610 30124 raft_consensus.cc:359] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ac97c618348459ebe1198ead17338e6" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 43379 } }
I20260812 06:17:11.523757 30124 raft_consensus.cc:385] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.523808 30124 raft_consensus.cc:740] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3ac97c618348459ebe1198ead17338e6, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.523970 30124 consensus_queue.cc:260] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [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: "3ac97c618348459ebe1198ead17338e6" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 43379 } }
I20260812 06:17:11.524091 30124 raft_consensus.cc:399] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.524140 30124 raft_consensus.cc:493] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.524196 30124 raft_consensus.cc:3060] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.525358 30124 raft_consensus.cc:515] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ac97c618348459ebe1198ead17338e6" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 43379 } }
I20260812 06:17:11.525544 30124 leader_election.cc:304] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [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: 3ac97c618348459ebe1198ead17338e6; no voters: 
I20260812 06:17:11.525820 30124 leader_election.cc:290] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.525955 30126 raft_consensus.cc:2804] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.526206 30126 raft_consensus.cc:697] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 1 LEADER]: Becoming Leader. State: Replica: 3ac97c618348459ebe1198ead17338e6, State: Running, Role: LEADER
I20260812 06:17:11.526233 30124 ts_tablet_manager.cc:1434] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:11.526510 30110 heartbeater.cc:499] Master 127.29.57.126:37555 was elected leader, sending a full tablet report...
I20260812 06:17:11.526917 30126 consensus_queue.cc:237] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [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: "3ac97c618348459ebe1198ead17338e6" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 43379 } }
I20260812 06:17:11.530548 29959 catalog_manager.cc:5719] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3ac97c618348459ebe1198ead17338e6 (127.29.57.65). New cstate: current_term: 1 leader_uuid: "3ac97c618348459ebe1198ead17338e6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ac97c618348459ebe1198ead17338e6" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 43379 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:11.600327 29925 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.024s	sys 0.004s
I20260812 06:17:11.724588 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=15.086190
I20260812 06:17:11.901435 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.176s	user 0.133s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":231,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1002,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43168,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":159,"threads_started":1,"update_count":1500}
I20260812 06:17:11.902805 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling LogGCOp(c2c427f4bd894d3989a60bb5c48eade4): free 8725963 bytes of WAL
I20260812 06:17:11.903203 30042 log_reader.cc:385] T c2c427f4bd894d3989a60bb5c48eade4: removed 1 log segments from log reader
I20260812 06:17:11.903275 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000001 (ops 1-6)
I20260812 06:17:11.905880 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: LogGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:11.906275 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:11.921784 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.922345 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:12.067965 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.145s	user 0.121s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":385,"lbm_read_time_us":10803,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29675,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22144,"thread_start_us":324,"threads_started":5,"update_count":2000}
I20260812 06:17:12.068538 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4): 12308960 bytes on disk
I20260812 06:17:12.069227 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.069916 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=10.126437
I20260812 06:17:12.117781 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.048s	user 0.012s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24633,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.118315 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:12.146957 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.028s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.147500 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:12.164808 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.165555 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:12.327370 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.162s	user 0.107s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":234,"lbm_read_time_us":11178,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34068,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:17:12.327937 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=11.118625
I20260812 06:17:12.376837 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.049s	user 0.031s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19999,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.377441 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:12.388216 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3960,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.389016 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:12.519598 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.130s	user 0.105s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":9883,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24414,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:17:12.520196 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=10.126437
I20260812 06:17:12.578090 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.058s	user 0.036s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18270,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.578666 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:12.592078 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.592854 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:12.760344 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.167s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":13235,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29660,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.761057 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=10.126437
I20260812 06:17:12.818734 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.057s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20309,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.819386 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:12.830549 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.831274 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:12.954134 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.123s	user 0.086s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":334,"lbm_read_time_us":9126,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23611,"lbm_writes_lt_1ms":443,"mutex_wait_us":105,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.954774 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=10.126437
I20260812 06:17:12.998478 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19018,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.999125 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:13.011473 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.012046 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:13.159222 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.147s	user 0.112s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":480,"lbm_read_time_us":10737,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29408,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:17:13.160022 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=10.126437
I20260812 06:17:13.199361 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.039s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15806,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.200165 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:13.243227 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.043s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":288,"dirs.run_wall_time_us":1466,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2345,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:13.244077 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4): 462 bytes on disk
I20260812 06:17:13.244534 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.245009 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=3.181125
I20260812 06:17:13.256996 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4598,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:13.257580 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling LogGCOp(c2c427f4bd894d3989a60bb5c48eade4): free 124257178 bytes of WAL
I20260812 06:17:13.257812 30042 log_reader.cc:385] T c2c427f4bd894d3989a60bb5c48eade4: removed 12 log segments from log reader
I20260812 06:17:13.257853 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000002 (ops 7-11)
I20260812 06:17:13.257884 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000003 (ops 12-16)
I20260812 06:17:13.257951 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000004 (ops 17-20)
I20260812 06:17:13.257998 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000005 (ops 21-25)
I20260812 06:17:13.258054 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000006 (ops 26-30)
I20260812 06:17:13.258095 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000007 (ops 31-35)
I20260812 06:17:13.258133 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000008 (ops 36-40)
I20260812 06:17:13.258170 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000009 (ops 41-45)
I20260812 06:17:13.258209 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000010 (ops 46-50)
I20260812 06:17:13.258246 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000011 (ops 51-55)
I20260812 06:17:13.258284 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000012 (ops 56-60)
I20260812 06:17:13.258327 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000013 (ops 61-65)
I20260812 06:17:13.286872 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: LogGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:13.287484 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:13.299998 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4473,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.300565 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:13.315848 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5954,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.316560 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:13.507913 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.191s	user 0.123s	sys 0.055s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836366,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":712,"lbm_read_time_us":12810,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37831,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14592,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:13.508641 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=14.095187
I20260812 06:17:13.565485 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.057s	user 0.043s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23638,"lbm_writes_lt_1ms":403,"mutex_wait_us":3,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.566138 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:13.581894 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.582451 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:13.737641 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.155s	user 0.098s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":403,"lbm_read_time_us":10726,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30598,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:13.738778 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=12.110812
I20260812 06:17:13.784336 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.045s	user 0.036s	sys 0.007s Metrics: {"bytes_written":13620265,"delete_count":0,"lbm_write_time_us":20350,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:17:13.784852 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.196750
I20260812 06:17:13.798316 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.013s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3300,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:17:13.799031 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:13.952320 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.153s	user 0.100s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631283,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":385,"lbm_read_time_us":9847,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25671,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:17:13.953052 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=14.095187
I20260812 06:17:14.005757 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.053s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23597,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.006436 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:14.028862 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.022s	user 0.007s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.029620 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:14.208645 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.179s	user 0.118s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1532,"lbm_read_time_us":12126,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32544,"lbm_writes_lt_1ms":543,"mutex_wait_us":358,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73984,"update_count":2500}
I20260812 06:17:14.209365 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=11.118625
I20260812 06:17:14.257872 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.048s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":21083,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:14.258558 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:14.277007 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.018s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:17:14.277508 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:14.293116 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":6072,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:14.293792 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:14.457675 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.164s	user 0.099s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733839,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":5129,"lbm_read_time_us":10418,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29547,"lbm_writes_lt_1ms":543,"mutex_wait_us":2438,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:14.458742 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=10.126437
I20260812 06:17:14.494764 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.036s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16039,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.495332 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:14.512442 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6515,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.513168 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:14.645224 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.132s	user 0.093s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1254,"lbm_read_time_us":8883,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25311,"lbm_writes_lt_1ms":443,"mutex_wait_us":417,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:17:14.646018 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=11.118625
I20260812 06:17:14.683175 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.037s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16057,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:14.683938 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:14.701583 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.017s	user 0.002s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5985,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.702178 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:14.744665 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.042s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1514,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2464,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:14.745652 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=3.181125
I20260812 06:17:14.765791 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.020s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7143,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.766330 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling LogGCOp(c2c427f4bd894d3989a60bb5c48eade4): free 121006499 bytes of WAL
I20260812 06:17:14.766587 30042 log_reader.cc:385] T c2c427f4bd894d3989a60bb5c48eade4: removed 12 log segments from log reader
I20260812 06:17:14.766657 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000014 (ops 66-70)
I20260812 06:17:14.766710 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000015 (ops 71-74)
I20260812 06:17:14.766748 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000016 (ops 75-79)
I20260812 06:17:14.766784 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000017 (ops 80-84)
I20260812 06:17:14.766822 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000018 (ops 85-89)
I20260812 06:17:14.766862 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000019 (ops 90-94)
I20260812 06:17:14.766906 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000020 (ops 95-99)
I20260812 06:17:14.766945 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000021 (ops 100-104)
I20260812 06:17:14.767024 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000022 (ops 105-109)
I20260812 06:17:14.767066 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000023 (ops 110-114)
I20260812 06:17:14.767105 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000024 (ops 115-119)
I20260812 06:17:14.767145 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000025 (ops 120-124)
I20260812 06:17:14.794694 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: LogGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:14.795351 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:14.810138 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.015s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4259,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.810706 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling LogGCOp(c2c427f4bd894d3989a60bb5c48eade4): free 11564877 bytes of WAL
I20260812 06:17:14.811234 30042 log_reader.cc:385] T c2c427f4bd894d3989a60bb5c48eade4: removed 1 log segments from log reader
I20260812 06:17:14.811367 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000026 (ops 125-128)
I20260812 06:17:14.813743 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: LogGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:14.814110 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:14.827286 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.827760 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4): 472 bytes on disk
I20260812 06:17:14.828307 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.829051 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:15.021934 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.193s	user 0.160s	sys 0.030s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938885,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":624,"lbm_read_time_us":12343,"lbm_reads_lt_1ms":767,"lbm_write_time_us":39639,"lbm_writes_lt_1ms":743,"mutex_wait_us":94,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:17:15.022878 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=14.095187
I20260812 06:17:15.087070 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.064s	user 0.045s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29132,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.087641 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=3.181125
I20260812 06:17:15.108019 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.020s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8047,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:15.108551 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:15.119575 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.120621 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:15.290550 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.170s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836245,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":775,"lbm_read_time_us":12945,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35265,"lbm_writes_lt_1ms":643,"mutex_wait_us":395,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":54784,"update_count":3000}
I20260812 06:17:15.291213 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=14.095187
I20260812 06:17:15.347503 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.056s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22739,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.348006 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:15.359891 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.360396 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:15.518469 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.158s	user 0.105s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":917,"lbm_read_time_us":11082,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31433,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:15.519390 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=10.126437
I20260812 06:17:15.557520 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16145,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.558461 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:15.576531 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.577127 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:15.726012 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.149s	user 0.090s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":882,"lbm_read_time_us":10843,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23637,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:17:15.726665 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=11.118625
I20260812 06:17:15.765470 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.039s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16371,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":1550}
I20260812 06:17:15.766196 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:15.799472 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.033s	user 0.005s	sys 0.018s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4723,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:15.800173 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:15.816301 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":6050,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:15.816893 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:16.005219 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.188s	user 0.125s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733840,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":684,"lbm_read_time_us":12185,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29730,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:17:16.006119 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=14.095187
I20260812 06:17:16.061020 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.054s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21717,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.061558 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:16.073279 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.073797 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:16.272996 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.199s	user 0.121s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":12528,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33205,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:17:16.273767 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=14.095187
I20260812 06:17:16.327773 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.054s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22282,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.328290 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:16.340406 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.340914 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:16.376087 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushMRSOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1461,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1806,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:16.376783 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling LogGCOp(c2c427f4bd894d3989a60bb5c48eade4): free 128867725 bytes of WAL
I20260812 06:17:16.377036 30042 log_reader.cc:385] T c2c427f4bd894d3989a60bb5c48eade4: removed 13 log segments from log reader
I20260812 06:17:16.377099 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000027 (ops 129-133)
I20260812 06:17:16.377152 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000028 (ops 134-138)
I20260812 06:17:16.377211 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000029 (ops 139-142)
I20260812 06:17:16.377252 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000030 (ops 143-147)
I20260812 06:17:16.377287 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000031 (ops 148-152)
I20260812 06:17:16.377324 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000032 (ops 153-156)
I20260812 06:17:16.377369 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000033 (ops 157-161)
I20260812 06:17:16.377406 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000034 (ops 162-166)
I20260812 06:17:16.377442 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000035 (ops 167-171)
I20260812 06:17:16.377478 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000036 (ops 172-176)
I20260812 06:17:16.377516 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000037 (ops 177-180)
I20260812 06:17:16.377552 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000038 (ops 181-185)
I20260812 06:17:16.377589 30042 log.cc:1079] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/c2c427f4bd894d3989a60bb5c48eade4/wal-000000039 (ops 186-190)
I20260812 06:17:16.408195 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: LogGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:16.409740 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=3.181125
I20260812 06:17:16.431311 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.021s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4389831,"delete_count":0,"lbm_write_time_us":6088,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:17:16.431829 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4): 493 bytes on disk
I20260812 06:17:16.432296 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: UndoDeltaBlockGCOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.432859 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=2.188937
I20260812 06:17:16.448029 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5955,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:16.448686 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:16.647806 29925 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.047s	user 1.888s	sys 0.101s
I20260812 06:17:16.683609 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.235s	user 0.155s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938782,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15731,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40962,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:17:16.684180 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=14.095187
I20260812 06:17:16.718358 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: FlushDeltaMemStoresOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.034s	user 0.021s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.718901 30112 maintenance_manager.cc:419] P 3ac97c618348459ebe1198ead17338e6: Scheduling MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4): perf score=1.000000
I20260812 06:17:16.769290 29925 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.121s	user 0.003s	sys 0.000s
I20260812 06:17:16.770171 29925 tablet_server.cc:179] TabletServer@127.29.57.65:0 shutting down...
I20260812 06:17:16.849401 30042 maintenance_manager.cc:643] P 3ac97c618348459ebe1198ead17338e6: MajorDeltaCompactionOp(c2c427f4bd894d3989a60bb5c48eade4) complete. Timing: real 0.130s	user 0.093s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1233,"lbm_read_time_us":9868,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27256,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":53504,"update_count":2000}
I20260812 06:17:16.850189 29925 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:16.850670 29925 tablet_replica.cc:333] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6: stopping tablet replica
I20260812 06:17:16.850889 29925 raft_consensus.cc:2243] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:16.851214 29925 raft_consensus.cc:2272] T c2c427f4bd894d3989a60bb5c48eade4 P 3ac97c618348459ebe1198ead17338e6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:16.867843 29925 tablet_server.cc:196] TabletServer@127.29.57.65:0 shutdown complete.
I20260812 06:17:16.890537 29925 master.cc:562] Master@127.29.57.126:37555 shutting down...
I20260812 06:17:16.895298 29925 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:16.895535 29925 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:16.895641 29925 tablet_replica.cc:333] T 00000000000000000000000000000000 P 82b47f783d1246a88f9136ae2b713016: stopping tablet replica
I20260812 06:17:16.908535 29925 master.cc:584] Master@127.29.57.126:37555 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5715 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:17.001884 29925 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.57.126:37583
I20260812 06:17:17.002333 29925 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:17.004848 30145 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.004784 30148 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.004937 30146 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:17.005194 29925 server_base.cc:1061] running on GCE node
I20260812 06:17:17.005380 29925 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:17.005422 29925 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:17.005438 29925 hybrid_clock.cc:648] HybridClock initialized: now 1786515437005438 us; error 0 us; skew 500 ppm
I20260812 06:17:17.006439 29925 webserver.cc:533] Webserver started at http://127.29.57.126:35675/ using document root <none> and password file <none>
I20260812 06:17:17.006626 29925 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:17.006711 29925 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:17.006795 29925 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:17.007287 29925 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/master-0-root/instance:
uuid: "3b2f0b45792040d5ba4874cd0bd5e131"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-w206"
I20260812 06:17:17.009048 29925 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:17.010139 30154 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.010452 29925 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:17.010522 29925 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/master-0-root
uuid: "3b2f0b45792040d5ba4874cd0bd5e131"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-w206"
I20260812 06:17:17.010748 29925 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:17.037289 29925 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:17.037875 29925 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:17.042508 29925 rpc_server.cc:307] RPC server started. Bound to: 127.29.57.126:37583
I20260812 06:17:17.046995 30209 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.57.126:37583 every 8 connection(s)
I20260812 06:17:17.059314 30211 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:17.061515 30211 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131: Bootstrap starting.
I20260812 06:17:17.062333 30211 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:17.063578 30211 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131: No bootstrap required, opened a new log
I20260812 06:17:17.064026 30211 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b2f0b45792040d5ba4874cd0bd5e131" member_type: VOTER }
I20260812 06:17:17.064133 30211 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:17.064163 30211 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3b2f0b45792040d5ba4874cd0bd5e131, State: Initialized, Role: FOLLOWER
I20260812 06:17:17.064289 30211 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [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: "3b2f0b45792040d5ba4874cd0bd5e131" member_type: VOTER }
I20260812 06:17:17.064354 30211 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:17.064381 30211 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:17.064421 30211 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:17.065187 30211 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b2f0b45792040d5ba4874cd0bd5e131" member_type: VOTER }
I20260812 06:17:17.065320 30211 leader_election.cc:304] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [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: 3b2f0b45792040d5ba4874cd0bd5e131; no voters: 
I20260812 06:17:17.065501 30211 leader_election.cc:290] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:17.065663 30215 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:17.065909 30215 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 1 LEADER]: Becoming Leader. State: Replica: 3b2f0b45792040d5ba4874cd0bd5e131, State: Running, Role: LEADER
I20260812 06:17:17.066116 30211 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:17.066116 30215 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [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: "3b2f0b45792040d5ba4874cd0bd5e131" member_type: VOTER }
I20260812 06:17:17.066675 30216 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3b2f0b45792040d5ba4874cd0bd5e131" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b2f0b45792040d5ba4874cd0bd5e131" member_type: VOTER } }
I20260812 06:17:17.066689 30217 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3b2f0b45792040d5ba4874cd0bd5e131. Latest consensus state: current_term: 1 leader_uuid: "3b2f0b45792040d5ba4874cd0bd5e131" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b2f0b45792040d5ba4874cd0bd5e131" member_type: VOTER } }
I20260812 06:17:17.066798 30217 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:17.067073 30216 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:17.067204 30220 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:17.068011 30220 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:17.068593 29925 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:17.070077 30220 catalog_manager.cc:1383] Generated new cluster ID: 072d9b373d30448a8e1284e6ef215374
I20260812 06:17:17.070147 30220 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:17.083163 30220 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:17.083855 30220 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:17.089637 30220 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131: Generated new TSK 0
I20260812 06:17:17.089861 30220 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:17.101305 29925 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:17.104146 30238 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:17.104303 29925 server_base.cc:1061] running on GCE node
W20260812 06:17:17.104617 30242 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.104166 30240 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:17.105010 29925 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:17.105084 29925 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:17.105108 29925 hybrid_clock.cc:648] HybridClock initialized: now 1786515437105108 us; error 0 us; skew 500 ppm
I20260812 06:17:17.106710 29925 webserver.cc:533] Webserver started at http://127.29.57.65:33541/ using document root <none> and password file <none>
I20260812 06:17:17.106871 29925 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:17.106916 29925 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:17.107056 29925 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:17.107467 29925 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/instance:
uuid: "35d8a9f16f524038b9ef817eb03a83f9"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-w206"
I20260812 06:17:17.109486 29925 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:17.110849 30247 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.111213 29925 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:17.111297 29925 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root
uuid: "35d8a9f16f524038b9ef817eb03a83f9"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-w206"
I20260812 06:17:17.111429 29925 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:17.120335 29925 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:17.120945 29925 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:17.121330 29925 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:17.121915 29925 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:17.121984 29925 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.122046 29925 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:17.122077 29925 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.128662 29925 rpc_server.cc:307] RPC server started. Bound to: 127.29.57.65:45451
I20260812 06:17:17.128732 30319 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.57.65:45451 every 8 connection(s)
I20260812 06:17:17.135123 30320 heartbeater.cc:344] Connected to a master server at 127.29.57.126:37583
I20260812 06:17:17.135295 30320 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:17.135614 30320 heartbeater.cc:507] Master 127.29.57.126:37583 requested a full tablet report, sending...
I20260812 06:17:17.136493 30171 ts_manager.cc:194] Registered new tserver with Master: 35d8a9f16f524038b9ef817eb03a83f9 (127.29.57.65:45451)
I20260812 06:17:17.137039 29925 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007860852s
I20260812 06:17:17.137336 30171 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33648
I20260812 06:17:17.146200 30171 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33658:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:17.156126 30280 tablet_service.cc:1511] Processing CreateTablet for tablet 8bd7eb0285d9418ea63260b286365e61 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ddec8f2202f340a0a9a687e14ab8c629]), partition=
I20260812 06:17:17.156483 30280 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8bd7eb0285d9418ea63260b286365e61. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:17.158964 30333 tablet_bootstrap.cc:492] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Bootstrap starting.
I20260812 06:17:17.160075 30333 tablet_bootstrap.cc:654] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:17.161325 30333 tablet_bootstrap.cc:492] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: No bootstrap required, opened a new log
I20260812 06:17:17.161461 30333 ts_tablet_manager.cc:1403] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:17.162026 30333 raft_consensus.cc:359] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35d8a9f16f524038b9ef817eb03a83f9" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 45451 } }
I20260812 06:17:17.162154 30333 raft_consensus.cc:385] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:17.162189 30333 raft_consensus.cc:740] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 35d8a9f16f524038b9ef817eb03a83f9, State: Initialized, Role: FOLLOWER
I20260812 06:17:17.162351 30333 consensus_queue.cc:260] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [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: "35d8a9f16f524038b9ef817eb03a83f9" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 45451 } }
I20260812 06:17:17.162494 30333 raft_consensus.cc:399] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:17.162524 30333 raft_consensus.cc:493] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:17.162556 30333 raft_consensus.cc:3060] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:17.163515 30333 raft_consensus.cc:515] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35d8a9f16f524038b9ef817eb03a83f9" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 45451 } }
I20260812 06:17:17.163671 30333 leader_election.cc:304] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [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: 35d8a9f16f524038b9ef817eb03a83f9; no voters: 
I20260812 06:17:17.163944 30333 leader_election.cc:290] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:17.164214 30335 raft_consensus.cc:2804] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:17.164287 30333 ts_tablet_manager.cc:1434] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:17.164321 30335 raft_consensus.cc:697] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 1 LEADER]: Becoming Leader. State: Replica: 35d8a9f16f524038b9ef817eb03a83f9, State: Running, Role: LEADER
I20260812 06:17:17.164323 30320 heartbeater.cc:499] Master 127.29.57.126:37583 was elected leader, sending a full tablet report...
I20260812 06:17:17.164489 30335 consensus_queue.cc:237] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [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: "35d8a9f16f524038b9ef817eb03a83f9" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 45451 } }
I20260812 06:17:17.166299 30171 catalog_manager.cc:5719] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 35d8a9f16f524038b9ef817eb03a83f9 (127.29.57.65). New cstate: current_term: 1 leader_uuid: "35d8a9f16f524038b9ef817eb03a83f9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35d8a9f16f524038b9ef817eb03a83f9" member_type: VOTER last_known_addr { host: "127.29.57.65" port: 45451 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:17.229125 29925 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.012s	sys 0.010s
I20260812 06:17:17.379735 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushMRSOp(8bd7eb0285d9418ea63260b286365e61): perf score=19.054940
I20260812 06:17:17.548758 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushMRSOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.169s	user 0.111s	sys 0.053s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":114,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1090,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45137,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:17.549496 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling LogGCOp(8bd7eb0285d9418ea63260b286365e61): free 20743880 bytes of WAL
I20260812 06:17:17.549793 30252 log_reader.cc:385] T 8bd7eb0285d9418ea63260b286365e61: removed 2 log segments from log reader
I20260812 06:17:17.549866 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000001 (ops 1-6)
I20260812 06:17:17.549918 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000002 (ops 7-11)
I20260812 06:17:17.555814 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: LogGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:17.556293 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61): 16411396 bytes on disk
I20260812 06:17:17.556846 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.557283 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:17.571830 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.014s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.572373 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:17.737893 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.165s	user 0.094s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1316,"lbm_read_time_us":11687,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25499,"lbm_writes_lt_1ms":443,"mutex_wait_us":260,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24960,"thread_start_us":377,"threads_started":5,"update_count":2000}
I20260812 06:17:17.738513 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=11.118625
I20260812 06:17:17.776384 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.038s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16342,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:17.777011 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:17.789403 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.789844 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:17.929682 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.140s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":8426,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29271,"lbm_writes_lt_1ms":443,"mutex_wait_us":93,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:17:17.933350 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=10.126437
I20260812 06:17:17.981232 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.048s	user 0.024s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19266,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.981801 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:17.997035 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.997591 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:18.130157 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.132s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":783,"lbm_read_time_us":9326,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25540,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:17:18.130765 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=10.126437
I20260812 06:17:18.173609 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.043s	user 0.022s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13530,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.174158 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:18.185058 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.006s	sys 0.003s 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:17:18.185552 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:18.345901 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.160s	user 0.116s	sys 0.044s 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":594,"lbm_read_time_us":12034,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25058,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:17:18.346513 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=10.126437
I20260812 06:17:18.379303 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.033s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14388,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.380048 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:18.396806 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.017s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.397282 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:18.538491 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.141s	user 0.120s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":9775,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28548,"lbm_writes_lt_1ms":443,"mutex_wait_us":818,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:17:18.539348 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=10.126437
I20260812 06:17:18.583578 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.044s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18618,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.584131 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:18.596789 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.597321 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:18.746398 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.149s	user 0.121s	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":251,"lbm_read_time_us":10563,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29743,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:17:18.747207 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=10.126437
I20260812 06:17:18.797168 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.050s	user 0.021s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18016,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.797847 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:18.809227 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.809957 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushMRSOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:18.849062 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushMRSOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.039s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":1659,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1758,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:18.849750 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling LogGCOp(8bd7eb0285d9418ea63260b286365e61): free 112239259 bytes of WAL
I20260812 06:17:18.850006 30252 log_reader.cc:385] T 8bd7eb0285d9418ea63260b286365e61: removed 11 log segments from log reader
I20260812 06:17:18.850050 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000003 (ops 12-16)
I20260812 06:17:18.850080 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000004 (ops 17-21)
I20260812 06:17:18.850137 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000005 (ops 22-26)
I20260812 06:17:18.850179 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000006 (ops 27-31)
I20260812 06:17:18.850220 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000007 (ops 32-36)
I20260812 06:17:18.850260 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000008 (ops 37-41)
I20260812 06:17:18.850301 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000009 (ops 42-46)
I20260812 06:17:18.850338 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000010 (ops 47-51)
I20260812 06:17:18.850389 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000011 (ops 52-56)
I20260812 06:17:18.850426 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000012 (ops 57-60)
I20260812 06:17:18.850472 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000013 (ops 61-65)
I20260812 06:17:18.876471 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: LogGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:18.876928 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61): 447 bytes on disk
I20260812 06:17:18.877367 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.877976 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=3.181125
I20260812 06:17:18.895740 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4810,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:18.896229 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:18.906621 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4022,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.907284 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:19.132468 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.225s	user 0.144s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":916,"lbm_read_time_us":14721,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37105,"lbm_writes_lt_1ms":643,"mutex_wait_us":131,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:17:19.133306 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:19.185775 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.052s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23862,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.186352 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:19.214311 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.028s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.214802 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:19.225972 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.226763 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:19.434172 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.207s	user 0.127s	sys 0.077s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":443,"lbm_read_time_us":13300,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33564,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":83712,"update_count":3000}
I20260812 06:17:19.434998 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=18.063937
I20260812 06:17:19.504132 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.069s	user 0.045s	sys 0.009s Metrics: {"bytes_written":19896952,"delete_count":0,"lbm_write_time_us":25242,"lbm_writes_lt_1ms":488,"reinsert_count":0,"update_count":2425}
I20260812 06:17:19.504767 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=3.181125
I20260812 06:17:19.520726 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4718029,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:17:19.521346 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:19.736163 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.215s	user 0.127s	sys 0.087s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":519,"lbm_read_time_us":16065,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35825,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":3000}
I20260812 06:17:19.736917 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:19.792510 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.049s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16861171,"delete_count":0,"lbm_write_time_us":22330,"lbm_writes_lt_1ms":414,"reinsert_count":0,"update_count":2055}
I20260812 06:17:19.793079 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:19.807982 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":5278,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:19.808431 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:19.818717 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.819200 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:20.039454 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.220s	user 0.146s	sys 0.073s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":784,"lbm_read_time_us":16476,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36057,"lbm_writes_lt_1ms":643,"mutex_wait_us":357,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":3000}
I20260812 06:17:20.040205 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=15.087375
I20260812 06:17:20.094595 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.054s	user 0.038s	sys 0.013s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":24438,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:20.095273 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:20.116079 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.020s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.116560 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:20.127578 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.128077 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:20.336519 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.208s	user 0.106s	sys 0.100s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":581,"lbm_read_time_us":13138,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35979,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:20.337471 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:20.383140 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.045s	user 0.018s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20522,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.383664 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushMRSOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:20.415302 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushMRSOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1608,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1598,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:20.416013 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling LogGCOp(8bd7eb0285d9418ea63260b286365e61): free 120553445 bytes of WAL
I20260812 06:17:20.416260 30252 log_reader.cc:385] T 8bd7eb0285d9418ea63260b286365e61: removed 12 log segments from log reader
I20260812 06:17:20.416306 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000014 (ops 66-70)
I20260812 06:17:20.416335 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000015 (ops 71-74)
I20260812 06:17:20.416352 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000016 (ops 75-79)
I20260812 06:17:20.416369 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000017 (ops 80-84)
I20260812 06:17:20.416422 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000018 (ops 85-89)
I20260812 06:17:20.416458 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000019 (ops 90-94)
I20260812 06:17:20.416515 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000020 (ops 95-98)
I20260812 06:17:20.416572 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000021 (ops 99-103)
I20260812 06:17:20.416623 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000022 (ops 104-108)
I20260812 06:17:20.416678 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000023 (ops 109-113)
I20260812 06:17:20.416719 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000024 (ops 114-118)
I20260812 06:17:20.416755 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000025 (ops 119-123)
I20260812 06:17:20.443856 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: LogGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:20.444346 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61): 483 bytes on disk
I20260812 06:17:20.444895 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.445461 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=3.181125
I20260812 06:17:20.464870 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7632,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:20.465332 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling LogGCOp(8bd7eb0285d9418ea63260b286365e61): free 8767123 bytes of WAL
I20260812 06:17:20.465547 30252 log_reader.cc:385] T 8bd7eb0285d9418ea63260b286365e61: removed 1 log segments from log reader
I20260812 06:17:20.465588 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000026 (ops 124-128)
I20260812 06:17:20.467676 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: LogGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:20.468055 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:20.478109 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.478591 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:20.714250 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.235s	user 0.127s	sys 0.103s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":45,"lbm_read_time_us":15984,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39910,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8704,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:17:20.714824 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=16.079562
I20260812 06:17:20.777063 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.062s	user 0.033s	sys 0.024s Metrics: {"bytes_written":18132916,"delete_count":0,"lbm_write_time_us":27781,"lbm_writes_lt_1ms":445,"reinsert_count":0,"update_count":2210}
I20260812 06:17:20.777578 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.196750
I20260812 06:17:20.788604 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2789859,"delete_count":0,"lbm_write_time_us":3160,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:17:20.789112 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:20.799237 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3969,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.799721 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:21.017551 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.218s	user 0.149s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877180,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":759,"lbm_read_time_us":16780,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34559,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3000}
I20260812 06:17:21.018374 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:21.073701 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.055s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24790,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:21.074280 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:21.086833 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.012s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.087378 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:21.261533 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.174s	user 0.125s	sys 0.049s 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":310,"lbm_read_time_us":13495,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31189,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:21.262203 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:21.322090 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.060s	user 0.030s	sys 0.026s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21662,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.322715 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:21.333602 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.334079 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:21.531482 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.197s	user 0.116s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":669,"lbm_read_time_us":13718,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33139,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:17:21.532264 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:21.590453 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.058s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.591095 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:21.602293 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.009s	sys 0.000s 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:17:21.602895 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:21.786372 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.183s	user 0.123s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":639,"lbm_read_time_us":13201,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28854,"lbm_writes_lt_1ms":543,"mutex_wait_us":283,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:21.787086 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:21.841023 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.054s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23311,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.841543 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:21.864243 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.864831 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:22.048697 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.184s	user 0.108s	sys 0.075s 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":206,"lbm_read_time_us":14430,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28190,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":157952,"update_count":2500}
I20260812 06:17:22.049268 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=14.095187
I20260812 06:17:22.098608 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.049s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21104,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.099256 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:22.110864 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.111508 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushMRSOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:22.149955 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushMRSOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.038s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":106,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1477,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2263,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:22.150848 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling LogGCOp(8bd7eb0285d9418ea63260b286365e61): free 132571538 bytes of WAL
I20260812 06:17:22.151155 30252 log_reader.cc:385] T 8bd7eb0285d9418ea63260b286365e61: removed 13 log segments from log reader
I20260812 06:17:22.151228 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000027 (ops 129-132)
I20260812 06:17:22.151292 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000028 (ops 133-137)
I20260812 06:17:22.151358 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000029 (ops 138-142)
I20260812 06:17:22.151402 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000030 (ops 143-146)
I20260812 06:17:22.151441 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000031 (ops 147-151)
I20260812 06:17:22.151482 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000032 (ops 152-156)
I20260812 06:17:22.151520 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000033 (ops 157-161)
I20260812 06:17:22.151559 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000034 (ops 162-166)
I20260812 06:17:22.151600 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000035 (ops 167-171)
I20260812 06:17:22.151640 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000036 (ops 172-176)
I20260812 06:17:22.151680 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000037 (ops 177-181)
I20260812 06:17:22.151721 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000038 (ops 182-186)
I20260812 06:17:22.151759 30252 log.cc:1079] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: Deleting log segment in path: /tmp/dist-test-taskpJtHgb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431275394-29925-0/minicluster-data/ts-0-root/wals/8bd7eb0285d9418ea63260b286365e61/wal-000000039 (ops 187-191)
I20260812 06:17:22.183617 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: LogGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.033s	user 0.004s	sys 0.028s Metrics: {}
I20260812 06:17:22.184047 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=3.181125
I20260812 06:17:22.197232 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4547,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:22.197682 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61): 492 bytes on disk
I20260812 06:17:22.198091 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: UndoDeltaBlockGCOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.198606 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=2.188937
I20260812 06:17:22.209676 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4500,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.211102 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61): perf score=1.000000
I20260812 06:17:22.343937 29925 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.115s	user 1.855s	sys 0.178s
I20260812 06:17:22.428957 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: MajorDeltaCompactionOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.218s	user 0.128s	sys 0.089s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":679,"lbm_read_time_us":16849,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35494,"lbm_writes_lt_1ms":743,"mutex_wait_us":24,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17920,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:22.430752 30322 maintenance_manager.cc:419] P 35d8a9f16f524038b9ef817eb03a83f9: Scheduling FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61): perf score=10.126437
I20260812 06:17:22.437668 29925 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.001s	sys 0.000s
I20260812 06:17:22.438333 29925 tablet_server.cc:179] TabletServer@127.29.57.65:0 shutting down...
I20260812 06:17:22.479553 30252 maintenance_manager.cc:643] P 35d8a9f16f524038b9ef817eb03a83f9: FlushDeltaMemStoresOp(8bd7eb0285d9418ea63260b286365e61) complete. Timing: real 0.048s	user 0.018s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16181,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:22.480577 29925 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:22.480859 29925 tablet_replica.cc:333] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9: stopping tablet replica
I20260812 06:17:22.481046 29925 raft_consensus.cc:2243] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.481278 29925 raft_consensus.cc:2272] T 8bd7eb0285d9418ea63260b286365e61 P 35d8a9f16f524038b9ef817eb03a83f9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.485249 29925 tablet_server.cc:196] TabletServer@127.29.57.65:0 shutdown complete.
I20260812 06:17:22.488204 29925 master.cc:562] Master@127.29.57.126:37583 shutting down...
I20260812 06:17:22.491662 29925 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.491853 29925 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.491945 29925 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3b2f0b45792040d5ba4874cd0bd5e131: stopping tablet replica
I20260812 06:17:22.504256 29925 master.cc:584] Master@127.29.57.126:37583 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5597 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11313 ms total)

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