[==========] 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:23.627835  5135 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.3.254:45537
I20260812 06:17:23.628875  5135 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:23.629478  5135 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:23.636088  5144 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:23.636165  5145 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:23.636271  5135 server_base.cc:1061] running on GCE node
W20260812 06:17:23.636371  5150 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:23.636834  5135 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:23.636921  5135 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:23.636951  5135 hybrid_clock.cc:648] HybridClock initialized: now 1786515443636950 us; error 0 us; skew 500 ppm
I20260812 06:17:23.638862  5135 webserver.cc:533] Webserver started at http://127.5.3.254:38681/ using document root <none> and password file <none>
I20260812 06:17:23.639555  5135 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:23.639643  5135 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:23.639961  5135 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:23.642601  5135 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/master-0-root/instance:
uuid: "57f1911e05f64b47bc3aa2f8ed772a6b"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-39l8"
I20260812 06:17:23.650475  5135 fs_manager.cc:696] Time spent creating directory manager: real 0.007s	user 0.004s	sys 0.000s
I20260812 06:17:23.653504  5159 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:23.655005  5135 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:23.655130  5135 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/master-0-root
uuid: "57f1911e05f64b47bc3aa2f8ed772a6b"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-39l8"
I20260812 06:17:23.655263  5135 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-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:23.676748  5135 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:23.677378  5135 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:23.677726  5135 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:23.687570  5239 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.3.254:45537 every 8 connection(s)
I20260812 06:17:23.687583  5135 rpc_server.cc:307] RPC server started. Bound to: 127.5.3.254:45537
I20260812 06:17:23.689813  5240 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:23.695170  5240 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b: Bootstrap starting.
I20260812 06:17:23.697371  5240 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:23.698238  5240 log.cc:826] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:23.699949  5240 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b: No bootstrap required, opened a new log
I20260812 06:17:23.702545  5240 raft_consensus.cc:359] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57f1911e05f64b47bc3aa2f8ed772a6b" member_type: VOTER }
I20260812 06:17:23.702813  5240 raft_consensus.cc:385] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:23.702912  5240 raft_consensus.cc:740] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 57f1911e05f64b47bc3aa2f8ed772a6b, State: Initialized, Role: FOLLOWER
I20260812 06:17:23.703474  5240 consensus_queue.cc:260] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [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: "57f1911e05f64b47bc3aa2f8ed772a6b" member_type: VOTER }
I20260812 06:17:23.703651  5240 raft_consensus.cc:399] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:23.703732  5240 raft_consensus.cc:493] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:23.703874  5240 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:23.704619  5240 raft_consensus.cc:515] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57f1911e05f64b47bc3aa2f8ed772a6b" member_type: VOTER }
I20260812 06:17:23.705031  5240 leader_election.cc:304] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [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: 57f1911e05f64b47bc3aa2f8ed772a6b; no voters: 
I20260812 06:17:23.705355  5240 leader_election.cc:290] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:23.705516  5246 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:23.705755  5246 raft_consensus.cc:697] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 1 LEADER]: Becoming Leader. State: Replica: 57f1911e05f64b47bc3aa2f8ed772a6b, State: Running, Role: LEADER
I20260812 06:17:23.706197  5246 consensus_queue.cc:237] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [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: "57f1911e05f64b47bc3aa2f8ed772a6b" member_type: VOTER }
I20260812 06:17:23.706275  5240 sys_catalog.cc:565] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:23.708137  5247 sys_catalog.cc:455] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "57f1911e05f64b47bc3aa2f8ed772a6b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57f1911e05f64b47bc3aa2f8ed772a6b" member_type: VOTER } }
I20260812 06:17:23.708160  5249 sys_catalog.cc:455] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 57f1911e05f64b47bc3aa2f8ed772a6b. Latest consensus state: current_term: 1 leader_uuid: "57f1911e05f64b47bc3aa2f8ed772a6b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57f1911e05f64b47bc3aa2f8ed772a6b" member_type: VOTER } }
I20260812 06:17:23.708267  5249 sys_catalog.cc:458] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:23.708268  5247 sys_catalog.cc:458] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:23.708757  5135 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:23.710942  5274 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:23.711004  5274 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:23.711078  5268 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:23.711791  5268 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:23.716228  5268 catalog_manager.cc:1383] Generated new cluster ID: 97a29c90002d47c5892ee68da9980d0a
I20260812 06:17:23.716302  5268 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:23.737317  5268 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:23.738541  5268 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:23.749351  5268 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b: Generated new TSK 0
I20260812 06:17:23.750015  5268 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:23.774065  5135 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:23.777114  5282 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:23.777212  5135 server_base.cc:1061] running on GCE node
W20260812 06:17:23.777109  5281 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:23.777351  5285 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:23.777585  5135 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:23.777642  5135 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:23.777665  5135 hybrid_clock.cc:648] HybridClock initialized: now 1786515443777665 us; error 0 us; skew 500 ppm
I20260812 06:17:23.778604  5135 webserver.cc:533] Webserver started at http://127.5.3.193:41921/ using document root <none> and password file <none>
I20260812 06:17:23.778800  5135 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:23.778859  5135 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:23.778936  5135 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:23.779407  5135 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/instance:
uuid: "8be77760f84c4aa58770ffb66b7fea98"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-39l8"
I20260812 06:17:23.781261  5135 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:23.782332  5291 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:23.782595  5135 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:23.782681  5135 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root
uuid: "8be77760f84c4aa58770ffb66b7fea98"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-39l8"
I20260812 06:17:23.782796  5135 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-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:23.804068  5135 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:23.804809  5135 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:23.805294  5135 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:23.806136  5135 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:23.806214  5135 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:23.806291  5135 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:23.806342  5135 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:23.813164  5135 rpc_server.cc:307] RPC server started. Bound to: 127.5.3.193:37975
I20260812 06:17:23.813241  5393 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.3.193:37975 every 8 connection(s)
I20260812 06:17:23.826352  5394 heartbeater.cc:344] Connected to a master server at 127.5.3.254:45537
I20260812 06:17:23.826627  5394 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:23.827123  5394 heartbeater.cc:507] Master 127.5.3.254:45537 requested a full tablet report, sending...
I20260812 06:17:23.828562  5185 ts_manager.cc:194] Registered new tserver with Master: 8be77760f84c4aa58770ffb66b7fea98 (127.5.3.193:37975)
I20260812 06:17:23.829506  5135 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015700709s
I20260812 06:17:23.829856  5185 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40770
I20260812 06:17:23.842887  5185 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40774:
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:23.857668  5334 tablet_service.cc:1511] Processing CreateTablet for tablet 6928d7589a4a40cb9bc2598203e6882d (DEFAULT_TABLE table=heavy-update-compaction-test [id=d747aa5990e34964a3e1b7ff03d9a7c5]), partition=
I20260812 06:17:23.858235  5334 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6928d7589a4a40cb9bc2598203e6882d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:23.861318  5422 tablet_bootstrap.cc:492] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Bootstrap starting.
I20260812 06:17:23.862211  5422 tablet_bootstrap.cc:654] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:23.863809  5422 tablet_bootstrap.cc:492] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: No bootstrap required, opened a new log
I20260812 06:17:23.863932  5422 ts_tablet_manager.cc:1403] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:23.864564  5422 raft_consensus.cc:359] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8be77760f84c4aa58770ffb66b7fea98" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 37975 } }
I20260812 06:17:23.864734  5422 raft_consensus.cc:385] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:23.864787  5422 raft_consensus.cc:740] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8be77760f84c4aa58770ffb66b7fea98, State: Initialized, Role: FOLLOWER
I20260812 06:17:23.864948  5422 consensus_queue.cc:260] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [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: "8be77760f84c4aa58770ffb66b7fea98" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 37975 } }
I20260812 06:17:23.865104  5422 raft_consensus.cc:399] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:23.865165  5422 raft_consensus.cc:493] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:23.865211  5422 raft_consensus.cc:3060] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:23.865988  5422 raft_consensus.cc:515] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8be77760f84c4aa58770ffb66b7fea98" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 37975 } }
I20260812 06:17:23.866146  5422 leader_election.cc:304] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [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: 8be77760f84c4aa58770ffb66b7fea98; no voters: 
I20260812 06:17:23.866492  5422 leader_election.cc:290] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:23.866590  5425 raft_consensus.cc:2804] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:23.866806  5425 raft_consensus.cc:697] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 1 LEADER]: Becoming Leader. State: Replica: 8be77760f84c4aa58770ffb66b7fea98, State: Running, Role: LEADER
I20260812 06:17:23.866928  5422 ts_tablet_manager.cc:1434] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:23.867020  5425 consensus_queue.cc:237] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [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: "8be77760f84c4aa58770ffb66b7fea98" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 37975 } }
I20260812 06:17:23.867209  5394 heartbeater.cc:499] Master 127.5.3.254:45537 was elected leader, sending a full tablet report...
I20260812 06:17:23.870116  5185 catalog_manager.cc:5719] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8be77760f84c4aa58770ffb66b7fea98 (127.5.3.193). New cstate: current_term: 1 leader_uuid: "8be77760f84c4aa58770ffb66b7fea98" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8be77760f84c4aa58770ffb66b7fea98" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 37975 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:23.930267  5135 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.016s	sys 0.008s
I20260812 06:17:24.064195  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d): perf score=19.054940
I20260812 06:17:24.244060  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.180s	user 0.129s	sys 0.048s Metrics: {"bytes_written":14153569,"cfile_init":1,"compiler_manager_pool.queue_time_us":214,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":924,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46582,"lbm_writes_lt_1ms":802,"mutex_wait_us":161,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":143616,"thread_start_us":146,"threads_started":1,"update_count":1725}
I20260812 06:17:24.245436  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:24.257541  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3487290,"delete_count":0,"lbm_write_time_us":4709,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:17:24.257966  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling LogGCOp(6928d7589a4a40cb9bc2598203e6882d): free 20743831 bytes of WAL
I20260812 06:17:24.258239  5301 log_reader.cc:385] T 6928d7589a4a40cb9bc2598203e6882d: removed 2 log segments from log reader
I20260812 06:17:24.258298  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000001 (ops 1-6)
I20260812 06:17:24.258358  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000002 (ops 7-11)
I20260812 06:17:24.264199  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: LogGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:24.264554  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d): 16411393 bytes on disk
I20260812 06:17:24.265156  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.265566  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.196750
I20260812 06:17:24.276594  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:24.277005  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:24.465152  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.188s	user 0.148s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774764,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":492,"lbm_read_time_us":13810,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30058,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":303,"threads_started":5,"update_count":2500}
I20260812 06:17:24.465634  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:24.512295  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.046s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18283,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.512861  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:24.527100  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5543,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.527534  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:24.667172  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.139s	user 0.097s	sys 0.040s 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":183,"lbm_read_time_us":9929,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24825,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:17:24.667814  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=7.149875
I20260812 06:17:24.690657  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.023s	user 0.012s	sys 0.008s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":9441,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:24.691203  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:24.702340  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.702960  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:24.816684  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.113s	user 0.084s	sys 0.027s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569855,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1045,"lbm_read_time_us":6206,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21494,"lbm_writes_lt_1ms":343,"mutex_wait_us":322,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:17:24.817251  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=7.149875
I20260812 06:17:24.849393  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.032s	user 0.018s	sys 0.011s Metrics: {"bytes_written":8861468,"delete_count":0,"lbm_write_time_us":15306,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":217,"reinsert_count":0,"update_count":1080}
I20260812 06:17:24.850155  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:24.866288  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4855,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:17:24.866770  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:24.987295  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.120s	user 0.096s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569851,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":534,"lbm_read_time_us":8267,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21136,"lbm_writes_lt_1ms":343,"mutex_wait_us":285,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":33152,"update_count":1500}
I20260812 06:17:24.987758  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:25.028796  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17403,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.029287  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:25.040342  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.040944  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:25.166865  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.126s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1178,"lbm_read_time_us":9592,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23530,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:25.167532  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:25.212513  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.045s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14532,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.212997  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:25.223683  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.224287  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:25.358968  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.134s	user 0.110s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":9512,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23265,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:17:25.359705  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:25.414994  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.055s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14896,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.415556  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:25.425908  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.426352  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:25.575738  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.149s	user 0.109s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1123,"lbm_read_time_us":10300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24571,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:17:25.576622  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:25.625113  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.048s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17625,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.625607  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:25.637894  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.638401  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:25.673125  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1245,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1619,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:25.673943  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling LogGCOp(6928d7589a4a40cb9bc2598203e6882d): free 121006515 bytes of WAL
I20260812 06:17:25.674206  5301 log_reader.cc:385] T 6928d7589a4a40cb9bc2598203e6882d: removed 12 log segments from log reader
I20260812 06:17:25.674253  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000003 (ops 12-16)
I20260812 06:17:25.674286  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000004 (ops 17-21)
I20260812 06:17:25.674345  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000005 (ops 22-26)
I20260812 06:17:25.674393  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000006 (ops 27-30)
I20260812 06:17:25.674413  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000007 (ops 31-35)
I20260812 06:17:25.674454  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000008 (ops 36-40)
I20260812 06:17:25.674501  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000009 (ops 41-45)
I20260812 06:17:25.674532  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000010 (ops 46-50)
I20260812 06:17:25.674599  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000011 (ops 51-55)
I20260812 06:17:25.674646  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000012 (ops 56-60)
I20260812 06:17:25.674690  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000013 (ops 61-65)
I20260812 06:17:25.674755  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000014 (ops 66-70)
I20260812 06:17:25.706234  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: LogGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:25.706845  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=6.157687
I20260812 06:17:25.735888  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.029s	user 0.008s	sys 0.020s Metrics: {"bytes_written":7671759,"delete_count":0,"lbm_write_time_us":9048,"lbm_writes_lt_1ms":190,"reinsert_count":0,"update_count":935}
I20260812 06:17:25.736492  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling LogGCOp(6928d7589a4a40cb9bc2598203e6882d): free 11564875 bytes of WAL
I20260812 06:17:25.736791  5301 log_reader.cc:385] T 6928d7589a4a40cb9bc2598203e6882d: removed 1 log segments from log reader
I20260812 06:17:25.736873  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000015 (ops 71-74)
I20260812 06:17:25.740165  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: LogGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:25.740617  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:25.960155  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.219s	user 0.128s	sys 0.079s Metrics: {"cfile_cache_miss":620,"cfile_cache_miss_bytes":28343901,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":502,"lbm_read_time_us":16100,"lbm_reads_lt_1ms":656,"lbm_write_time_us":35677,"lbm_writes_lt_1ms":630,"peak_mem_usage":73968633,"reinsert_count":0,"thread_start_us":74,"threads_started":1,"update_count":2935}
I20260812 06:17:25.960759  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=19.056125
I20260812 06:17:26.032374  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.071s	user 0.037s	sys 0.032s Metrics: {"bytes_written":21045631,"delete_count":0,"lbm_write_time_us":28799,"lbm_writes_lt_1ms":516,"reinsert_count":0,"update_count":2565}
I20260812 06:17:26.032923  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:26.045141  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4504,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.045977  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d): 483 bytes on disk
I20260812 06:17:26.046543  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.047112  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:26.237207  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.190s	user 0.132s	sys 0.057s Metrics: {"cfile_cache_miss":645,"cfile_cache_miss_bytes":29410418,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":13853,"lbm_reads_lt_1ms":685,"lbm_write_time_us":33354,"lbm_writes_lt_1ms":656,"peak_mem_usage":77116311,"reinsert_count":0,"update_count":3065}
I20260812 06:17:26.245908  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=14.095187
I20260812 06:17:26.285694  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.040s	user 0.020s	sys 0.017s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":17525,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.286290  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:26.300992  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.015s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.301434  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:26.474637  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.173s	user 0.117s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":682,"lbm_read_time_us":11621,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31217,"lbm_writes_lt_1ms":543,"mutex_wait_us":303,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:17:26.475147  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=14.095187
I20260812 06:17:26.535676  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.060s	user 0.021s	sys 0.027s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":18251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.536185  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:26.546634  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.547113  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:26.713433  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.166s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":506,"lbm_read_time_us":12014,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28669,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33280,"update_count":2500}
I20260812 06:17:26.713946  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=11.118625
I20260812 06:17:26.756213  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.042s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17192,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:26.756870  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:26.784214  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.027s	user 0.014s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5040,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.784793  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:26.800016  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.800662  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:26.972864  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.172s	user 0.120s	sys 0.050s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":186,"lbm_read_time_us":13533,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30393,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:17:26.973879  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=11.118625
I20260812 06:17:27.015024  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.041s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17816,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:27.015630  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:27.037923  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.022s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4547,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.038394  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:27.057643  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.058094  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:27.093768  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.036s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1166,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1481,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":2432}
I20260812 06:17:27.094491  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling LogGCOp(6928d7589a4a40cb9bc2598203e6882d): free 112239324 bytes of WAL
I20260812 06:17:27.094770  5301 log_reader.cc:385] T 6928d7589a4a40cb9bc2598203e6882d: removed 11 log segments from log reader
I20260812 06:17:27.094821  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000016 (ops 75-79)
I20260812 06:17:27.094851  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000017 (ops 80-84)
I20260812 06:17:27.094913  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000018 (ops 85-89)
I20260812 06:17:27.094947  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000019 (ops 90-94)
I20260812 06:17:27.094983  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000020 (ops 95-99)
I20260812 06:17:27.095050  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000021 (ops 100-104)
I20260812 06:17:27.095091  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000022 (ops 105-109)
I20260812 06:17:27.095132  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000023 (ops 110-114)
I20260812 06:17:27.095171  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000024 (ops 115-118)
I20260812 06:17:27.095219  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000025 (ops 119-123)
I20260812 06:17:27.095261  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000026 (ops 124-128)
I20260812 06:17:27.118819  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: LogGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.024s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:27.119365  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d): 446 bytes on disk
I20260812 06:17:27.119849  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.120422  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:27.137305  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.137768  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:27.147807  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.148416  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:27.384089  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.235s	user 0.134s	sys 0.088s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979862,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":696,"lbm_read_time_us":14801,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37937,"lbm_writes_lt_1ms":743,"mutex_wait_us":70,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:27.384903  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=18.063937
I20260812 06:17:27.454262  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.069s	user 0.029s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":23968,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:27.454813  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:27.465037  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.465581  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:27.661027  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.194s	user 0.117s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":650,"lbm_read_time_us":12197,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32925,"lbm_writes_lt_1ms":643,"mutex_wait_us":285,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:27.661577  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=14.095187
I20260812 06:17:27.703236  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.041s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18665,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.703828  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:27.835418  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.131s	user 0.095s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":622,"lbm_read_time_us":8281,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22572,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:17:27.839059  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:27.880090  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17805,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.880684  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:27.891860  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.892623  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:28.024605  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.132s	user 0.089s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":8637,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23873,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:17:28.025315  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:28.067500  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.042s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16187,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.068099  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:28.079430  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.080047  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:28.198937  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.119s	user 0.086s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1443,"lbm_read_time_us":7530,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22133,"lbm_writes_lt_1ms":443,"mutex_wait_us":675,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:17:28.199640  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:28.240605  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.041s	user 0.021s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16501,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.241163  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:28.256886  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.257496  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:28.386534  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.129s	user 0.112s	sys 0.016s 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":1401,"lbm_read_time_us":10557,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23740,"lbm_writes_lt_1ms":443,"mutex_wait_us":373,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:28.387135  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=10.126437
I20260812 06:17:28.431669  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.044s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14614,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.432193  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:28.442965  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.443436  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:28.485513  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushMRSOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.042s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1254,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1398,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:28.486171  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling LogGCOp(6928d7589a4a40cb9bc2598203e6882d): free 108988743 bytes of WAL
I20260812 06:17:28.486404  5301 log_reader.cc:385] T 6928d7589a4a40cb9bc2598203e6882d: removed 11 log segments from log reader
I20260812 06:17:28.486469  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000027 (ops 129-133)
I20260812 06:17:28.486519  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000028 (ops 134-138)
I20260812 06:17:28.486579  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000029 (ops 139-142)
I20260812 06:17:28.486621  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000030 (ops 143-147)
I20260812 06:17:28.486658  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000031 (ops 148-152)
I20260812 06:17:28.486706  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000032 (ops 153-157)
I20260812 06:17:28.486764  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000033 (ops 158-162)
I20260812 06:17:28.486817  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000034 (ops 163-167)
I20260812 06:17:28.486855  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000035 (ops 168-172)
I20260812 06:17:28.486893  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000036 (ops 173-177)
I20260812 06:17:28.486930  5301 log.cc:1079] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/6928d7589a4a40cb9bc2598203e6882d/wal-000000037 (ops 178-182)
I20260812 06:17:28.509562  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: LogGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:28.509991  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d): 447 bytes on disk
I20260812 06:17:28.510666  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: UndoDeltaBlockGCOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.511327  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=3.181125
I20260812 06:17:28.528750  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.017s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:28.529157  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:28.538666  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3731,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.539070  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:28.739059  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.200s	user 0.127s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877332,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1201,"lbm_read_time_us":13941,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33326,"lbm_writes_lt_1ms":643,"mutex_wait_us":632,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:28.739928  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=14.095187
I20260812 06:17:28.798992  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.059s	user 0.037s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20612,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.799505  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d): perf score=2.188937
I20260812 06:17:28.810108  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: FlushDeltaMemStoresOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.810940  5395 maintenance_manager.cc:419] P 8be77760f84c4aa58770ffb66b7fea98: Scheduling MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d): perf score=1.000000
I20260812 06:17:28.903961  5135 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.974s	user 1.759s	sys 0.223s
I20260812 06:17:28.969646  5135 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.001s	sys 0.000s
I20260812 06:17:28.970292  5135 tablet_server.cc:179] TabletServer@127.5.3.193:0 shutting down...
I20260812 06:17:28.977399  5301 maintenance_manager.cc:643] P 8be77760f84c4aa58770ffb66b7fea98: MajorDeltaCompactionOp(6928d7589a4a40cb9bc2598203e6882d) complete. Timing: real 0.166s	user 0.109s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":308,"lbm_read_time_us":12108,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29879,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:28.978076  5135 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:28.981423  5135 tablet_replica.cc:333] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98: stopping tablet replica
I20260812 06:17:28.981727  5135 raft_consensus.cc:2243] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:28.981932  5135 raft_consensus.cc:2272] T 6928d7589a4a40cb9bc2598203e6882d P 8be77760f84c4aa58770ffb66b7fea98 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:28.998476  5135 tablet_server.cc:196] TabletServer@127.5.3.193:0 shutdown complete.
I20260812 06:17:29.021582  5135 master.cc:562] Master@127.5.3.254:45537 shutting down...
I20260812 06:17:29.025444  5135 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.025651  5135 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.025753  5135 tablet_replica.cc:333] T 00000000000000000000000000000000 P 57f1911e05f64b47bc3aa2f8ed772a6b: stopping tablet replica
I20260812 06:17:29.038089  5135 master.cc:584] Master@127.5.3.254:45537 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5499 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:29.138087  5135 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.3.254:35783
I20260812 06:17:29.138630  5135 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:29.140769  5451 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:29.140810  5450 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:29.140847  5453 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:29.140885  5135 server_base.cc:1061] running on GCE node
I20260812 06:17:29.141144  5135 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.141193  5135 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:29.141209  5135 hybrid_clock.cc:648] HybridClock initialized: now 1786515449141209 us; error 0 us; skew 500 ppm
I20260812 06:17:29.142064  5135 webserver.cc:533] Webserver started at http://127.5.3.254:36583/ using document root <none> and password file <none>
I20260812 06:17:29.142242  5135 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.142311  5135 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.142416  5135 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.142887  5135 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/master-0-root/instance:
uuid: "deba1043b80a42b48453a8887e47e7e3"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-39l8"
I20260812 06:17:29.144392  5135 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.145323  5460 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:29.145591  5135 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.145685  5135 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/master-0-root
uuid: "deba1043b80a42b48453a8887e47e7e3"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-39l8"
I20260812 06:17:29.145774  5135 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-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:29.161310  5135 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.161746  5135 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.166272  5135 rpc_server.cc:307] RPC server started. Bound to: 127.5.3.254:35783
I20260812 06:17:29.170022  5542 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.3.254:35783 every 8 connection(s)
I20260812 06:17:29.171746  5544 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:29.173537  5544 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3: Bootstrap starting.
I20260812 06:17:29.174273  5544 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.175343  5544 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3: No bootstrap required, opened a new log
I20260812 06:17:29.175699  5544 raft_consensus.cc:359] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "deba1043b80a42b48453a8887e47e7e3" member_type: VOTER }
I20260812 06:17:29.175786  5544 raft_consensus.cc:385] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.175808  5544 raft_consensus.cc:740] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: deba1043b80a42b48453a8887e47e7e3, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.175964  5544 consensus_queue.cc:260] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [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: "deba1043b80a42b48453a8887e47e7e3" member_type: VOTER }
I20260812 06:17:29.176051  5544 raft_consensus.cc:399] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.176075  5544 raft_consensus.cc:493] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.176111  5544 raft_consensus.cc:3060] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.176720  5544 raft_consensus.cc:515] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "deba1043b80a42b48453a8887e47e7e3" member_type: VOTER }
I20260812 06:17:29.176831  5544 leader_election.cc:304] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [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: deba1043b80a42b48453a8887e47e7e3; no voters: 
I20260812 06:17:29.176980  5544 leader_election.cc:290] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.177134  5549 raft_consensus.cc:2804] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.177368  5549 raft_consensus.cc:697] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 1 LEADER]: Becoming Leader. State: Replica: deba1043b80a42b48453a8887e47e7e3, State: Running, Role: LEADER
I20260812 06:17:29.177448  5544 sys_catalog.cc:565] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:29.177500  5549 consensus_queue.cc:237] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [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: "deba1043b80a42b48453a8887e47e7e3" member_type: VOTER }
I20260812 06:17:29.177922  5552 sys_catalog.cc:455] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "deba1043b80a42b48453a8887e47e7e3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "deba1043b80a42b48453a8887e47e7e3" member_type: VOTER } }
I20260812 06:17:29.178037  5552 sys_catalog.cc:458] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.177940  5555 sys_catalog.cc:455] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader deba1043b80a42b48453a8887e47e7e3. Latest consensus state: current_term: 1 leader_uuid: "deba1043b80a42b48453a8887e47e7e3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "deba1043b80a42b48453a8887e47e7e3" member_type: VOTER } }
I20260812 06:17:29.178259  5555 sys_catalog.cc:458] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.178732  5559 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:29.179391  5559 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:29.179556  5135 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:29.181346  5559 catalog_manager.cc:1383] Generated new cluster ID: 056fecfd7f034bdf8cb9442eb0ee232f
I20260812 06:17:29.181428  5559 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:29.189741  5559 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:29.190344  5559 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:29.198208  5559 catalog_manager.cc:6092] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3: Generated new TSK 0
I20260812 06:17:29.198398  5559 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:29.212052  5135 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:29.214139  5585 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:29.214184  5589 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:29.214227  5135 server_base.cc:1061] running on GCE node
W20260812 06:17:29.214190  5584 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:29.214640  5135 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.214716  5135 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:29.214776  5135 hybrid_clock.cc:648] HybridClock initialized: now 1786515449214775 us; error 0 us; skew 500 ppm
I20260812 06:17:29.215705  5135 webserver.cc:533] Webserver started at http://127.5.3.193:34911/ using document root <none> and password file <none>
I20260812 06:17:29.215901  5135 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.215981  5135 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.216064  5135 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.216470  5135 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/instance:
uuid: "5453a662951445358737e236a1bfd9d2"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-39l8"
I20260812 06:17:29.217975  5135 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:29.218927  5596 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:29.219151  5135 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.219242  5135 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root
uuid: "5453a662951445358737e236a1bfd9d2"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-39l8"
I20260812 06:17:29.219332  5135 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-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:29.233196  5135 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.233666  5135 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.234021  5135 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:29.234535  5135 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:29.234598  5135 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.234660  5135 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:29.234712  5135 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.239270  5135 rpc_server.cc:307] RPC server started. Bound to: 127.5.3.193:33275
I20260812 06:17:29.240352  5700 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.3.193:33275 every 8 connection(s)
I20260812 06:17:29.248257  5702 heartbeater.cc:344] Connected to a master server at 127.5.3.254:35783
I20260812 06:17:29.248374  5702 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:29.248639  5702 heartbeater.cc:507] Master 127.5.3.254:35783 requested a full tablet report, sending...
I20260812 06:17:29.249333  5488 ts_manager.cc:194] Registered new tserver with Master: 5453a662951445358737e236a1bfd9d2 (127.5.3.193:33275)
I20260812 06:17:29.250070  5488 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41142
I20260812 06:17:29.250183  5135 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009951025s
I20260812 06:17:29.257525  5488 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41156:
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:29.266466  5638 tablet_service.cc:1511] Processing CreateTablet for tablet 0fc3e34ff757486b858094e813c91a38 (DEFAULT_TABLE table=heavy-update-compaction-test [id=24764aabc13f41e58756fbdf9518c7a3]), partition=
I20260812 06:17:29.266801  5638 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0fc3e34ff757486b858094e813c91a38. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:29.268929  5724 tablet_bootstrap.cc:492] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Bootstrap starting.
I20260812 06:17:29.269842  5724 tablet_bootstrap.cc:654] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.270977  5724 tablet_bootstrap.cc:492] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: No bootstrap required, opened a new log
I20260812 06:17:29.271117  5724 ts_tablet_manager.cc:1403] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:29.271560  5724 raft_consensus.cc:359] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5453a662951445358737e236a1bfd9d2" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 33275 } }
I20260812 06:17:29.271708  5724 raft_consensus.cc:385] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.271754  5724 raft_consensus.cc:740] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5453a662951445358737e236a1bfd9d2, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.271960  5724 consensus_queue.cc:260] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [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: "5453a662951445358737e236a1bfd9d2" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 33275 } }
I20260812 06:17:29.272058  5724 raft_consensus.cc:399] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.272126  5724 raft_consensus.cc:493] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.272204  5724 raft_consensus.cc:3060] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.272989  5724 raft_consensus.cc:515] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5453a662951445358737e236a1bfd9d2" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 33275 } }
I20260812 06:17:29.273154  5724 leader_election.cc:304] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [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: 5453a662951445358737e236a1bfd9d2; no voters: 
I20260812 06:17:29.273381  5724 leader_election.cc:290] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.273525  5726 raft_consensus.cc:2804] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.273761  5726 raft_consensus.cc:697] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 1 LEADER]: Becoming Leader. State: Replica: 5453a662951445358737e236a1bfd9d2, State: Running, Role: LEADER
I20260812 06:17:29.273785  5724 ts_tablet_manager.cc:1434] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:29.273816  5702 heartbeater.cc:499] Master 127.5.3.254:35783 was elected leader, sending a full tablet report...
I20260812 06:17:29.273929  5726 consensus_queue.cc:237] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [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: "5453a662951445358737e236a1bfd9d2" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 33275 } }
I20260812 06:17:29.275295  5488 catalog_manager.cc:5719] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5453a662951445358737e236a1bfd9d2 (127.5.3.193). New cstate: current_term: 1 leader_uuid: "5453a662951445358737e236a1bfd9d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5453a662951445358737e236a1bfd9d2" member_type: VOTER last_known_addr { host: "127.5.3.193" port: 33275 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:29.335413  5135 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.016s	sys 0.006s
I20260812 06:17:29.491011  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushMRSOp(0fc3e34ff757486b858094e813c91a38): perf score=19.054940
I20260812 06:17:29.645735  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushMRSOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.154s	user 0.094s	sys 0.055s Metrics: {"bytes_written":13784357,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":938,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39051,"lbm_writes_lt_1ms":803,"mutex_wait_us":1171,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":768,"update_count":1680}
I20260812 06:17:29.646497  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling LogGCOp(0fc3e34ff757486b858094e813c91a38): free 20290830 bytes of WAL
I20260812 06:17:29.646788  5601 log_reader.cc:385] T 0fc3e34ff757486b858094e813c91a38: removed 2 log segments from log reader
I20260812 06:17:29.646854  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000001 (ops 1-6)
I20260812 06:17:29.646907  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000002 (ops 7-10)
I20260812 06:17:29.650990  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: LogGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.004s	user 0.002s	sys 0.003s Metrics: {}
I20260812 06:17:29.651386  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38): 16821651 bytes on disk
I20260812 06:17:29.652201  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":130,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.652705  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=4.173312
I20260812 06:17:29.668093  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":6071828,"delete_count":0,"lbm_write_time_us":6293,"lbm_writes_lt_1ms":151,"reinsert_count":0,"update_count":740}
I20260812 06:17:29.668653  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:29.861903  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.193s	user 0.113s	sys 0.072s Metrics: {"cfile_cache_miss":516,"cfile_cache_miss_bytes":24159302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":661,"lbm_read_time_us":12747,"lbm_reads_lt_1ms":548,"lbm_write_time_us":30261,"lbm_writes_lt_1ms":527,"mutex_wait_us":36,"peak_mem_usage":60378572,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":386,"threads_started":5,"update_count":2420}
I20260812 06:17:29.862514  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=15.087375
I20260812 06:17:29.913120  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.050s	user 0.037s	sys 0.004s Metrics: {"bytes_written":16656050,"delete_count":0,"lbm_write_time_us":18880,"lbm_writes_lt_1ms":409,"reinsert_count":0,"update_count":2030}
I20260812 06:17:29.913555  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:30.068881  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.155s	user 0.096s	sys 0.058s Metrics: {"cfile_cache_miss":437,"cfile_cache_miss_bytes":20959301,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1151,"lbm_read_time_us":9883,"lbm_reads_lt_1ms":469,"lbm_write_time_us":25049,"lbm_writes_lt_1ms":449,"mutex_wait_us":50,"peak_mem_usage":50935538,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2030}
I20260812 06:17:30.069420  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:30.121811  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.052s	user 0.040s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23056,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.122388  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:30.146684  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.024s	user 0.016s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.147686  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:30.157015  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.009s	user 0.003s	sys 0.000s Metrics: {"bytes_written":1271930,"delete_count":0,"lbm_write_time_us":1221,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:17:30.157461  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=1.196750
I20260812 06:17:30.165380  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.008s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":2926,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:17:30.165817  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:30.361073  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.195s	user 0.123s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918238,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":154,"lbm_read_time_us":14492,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30270,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27904,"update_count":3000}
I20260812 06:17:30.361668  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:30.418617  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.057s	user 0.030s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19461,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.419212  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:30.436232  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.436833  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:30.612419  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.175s	user 0.113s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":11962,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28693,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:17:30.613168  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:30.672021  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.059s	user 0.023s	sys 0.034s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24988,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.672534  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:30.690593  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.691200  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:30.868078  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.177s	user 0.112s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1390,"lbm_read_time_us":11883,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29418,"lbm_writes_lt_1ms":543,"mutex_wait_us":432,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:17:30.868754  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:30.917637  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.049s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21644,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.918088  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:30.933881  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.934324  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushMRSOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:30.969919  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushMRSOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1422,"drs_written":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1594,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:30.970696  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling LogGCOp(0fc3e34ff757486b858094e813c91a38): free 121006404 bytes of WAL
I20260812 06:17:30.970968  5601 log_reader.cc:385] T 0fc3e34ff757486b858094e813c91a38: removed 12 log segments from log reader
I20260812 06:17:30.971037  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000003 (ops 11-15)
I20260812 06:17:30.971091  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000004 (ops 16-20)
I20260812 06:17:30.971154  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000005 (ops 21-24)
I20260812 06:17:30.971196  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000006 (ops 25-29)
I20260812 06:17:30.971232  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000007 (ops 30-34)
I20260812 06:17:30.971271  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000008 (ops 35-39)
I20260812 06:17:30.971308  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000009 (ops 40-44)
I20260812 06:17:30.971345  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000010 (ops 45-49)
I20260812 06:17:30.971382  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000011 (ops 50-54)
I20260812 06:17:30.971421  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000012 (ops 55-59)
I20260812 06:17:30.971457  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000013 (ops 60-64)
I20260812 06:17:30.971494  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000014 (ops 65-69)
I20260812 06:17:30.997566  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: LogGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:30.998095  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:31.015864  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.018s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.016300  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:31.026696  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.027247  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:31.274039  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.247s	user 0.143s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":666,"lbm_read_time_us":15412,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41715,"lbm_writes_lt_1ms":743,"mutex_wait_us":68,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:17:31.274834  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38): 462 bytes on disk
I20260812 06:17:31.275377  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4}
I20260812 06:17:31.276055  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=18.063937
I20260812 06:17:31.346897  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.071s	user 0.037s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25113,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:31.347409  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:31.362972  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.015s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.363615  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:31.570650  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.207s	user 0.126s	sys 0.081s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":487,"lbm_read_time_us":13033,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35455,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":3000}
I20260812 06:17:31.571234  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=15.087375
I20260812 06:17:31.627803  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.056s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":26788,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:17:31.628396  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:31.652367  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.024s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4893,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.652809  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:31.663130  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.663590  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:31.872608  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.209s	user 0.110s	sys 0.098s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918202,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":580,"lbm_read_time_us":13246,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33267,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":3000}
I20260812 06:17:31.873377  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:31.920557  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.047s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20814,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.921147  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:31.941593  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6681,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.942068  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:32.117841  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.176s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":162,"lbm_read_time_us":11562,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30224,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:32.118600  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:32.177270  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.058s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":20561,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.178012  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:32.190508  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.191040  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:32.368115  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.177s	user 0.115s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1409,"lbm_read_time_us":12344,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28442,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:32.371088  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:32.433763  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.062s	user 0.028s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23118,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.434329  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:32.445468  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.445927  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushMRSOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:32.487010  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushMRSOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.041s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1165,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1635,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:32.487684  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling LogGCOp(0fc3e34ff757486b858094e813c91a38): free 124710353 bytes of WAL
I20260812 06:17:32.487907  5601 log_reader.cc:385] T 0fc3e34ff757486b858094e813c91a38: removed 12 log segments from log reader
I20260812 06:17:32.487970  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000015 (ops 70-74)
I20260812 06:17:32.488023  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000016 (ops 75-79)
I20260812 06:17:32.488085  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000017 (ops 80-84)
I20260812 06:17:32.488138  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000018 (ops 85-89)
I20260812 06:17:32.488176  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000019 (ops 90-94)
I20260812 06:17:32.488219  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000020 (ops 95-99)
I20260812 06:17:32.488252  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000021 (ops 100-104)
I20260812 06:17:32.488287  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000022 (ops 105-109)
I20260812 06:17:32.488324  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000023 (ops 110-114)
I20260812 06:17:32.488361  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000024 (ops 115-119)
I20260812 06:17:32.488397  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000025 (ops 120-124)
I20260812 06:17:32.488432  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000026 (ops 125-129)
I20260812 06:17:32.515723  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: LogGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:32.516829  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=3.181125
I20260812 06:17:32.530231  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4307782,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:17:32.530747  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:32.541126  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3897533,"delete_count":0,"lbm_write_time_us":3988,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:32.541651  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:32.774294  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.232s	user 0.151s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020744,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":748,"lbm_read_time_us":16673,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37412,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":70,"threads_started":1,"update_count":3500}
I20260812 06:17:32.774871  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=18.063937
I20260812 06:17:32.836592  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.062s	user 0.043s	sys 0.013s Metrics: {"bytes_written":20512326,"delete_count":0,"lbm_write_time_us":26532,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:32.837106  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:32.849423  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.849983  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:33.035081  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.185s	user 0.121s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918108,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1241,"lbm_read_time_us":13187,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33437,"lbm_writes_lt_1ms":643,"mutex_wait_us":380,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":3000}
I20260812 06:17:33.035698  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38): 462 bytes on disk
I20260812 06:17:33.036108  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.036922  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:33.091347  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.054s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23884,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.091907  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:33.109179  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6485,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.109622  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:33.279569  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.170s	user 0.119s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":780,"lbm_read_time_us":11417,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30133,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:17:33.280351  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:33.321939  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.041s	user 0.023s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18921,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.322423  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:33.473557  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.151s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":187,"lbm_read_time_us":10551,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24299,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:17:33.474263  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=11.118625
I20260812 06:17:33.518026  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19524,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:33.518566  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:33.538822  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.020s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4405,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.539299  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:33.549492  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.010s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3468,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.550053  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:33.735026  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.185s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":734,"lbm_read_time_us":13545,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30633,"lbm_writes_lt_1ms":543,"mutex_wait_us":382,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":79616,"update_count":2500}
I20260812 06:17:33.735719  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=10.126437
I20260812 06:17:33.774014  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.038s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16801,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.774573  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:33.786199  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.786846  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:33.913296  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.126s	user 0.085s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":851,"lbm_read_time_us":8861,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23295,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":2000}
I20260812 06:17:33.914996  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=10.126437
I20260812 06:17:33.952265  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.037s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15712,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.952841  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:33.977833  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.025s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.978317  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:33.989126  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.989663  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushMRSOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:34.023422  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushMRSOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1229,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2180,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:34.024288  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling LogGCOp(0fc3e34ff757486b858094e813c91a38): free 124257516 bytes of WAL
I20260812 06:17:34.024546  5601 log_reader.cc:385] T 0fc3e34ff757486b858094e813c91a38: removed 12 log segments from log reader
I20260812 06:17:34.024632  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000027 (ops 130-134)
I20260812 06:17:34.024709  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000028 (ops 135-139)
I20260812 06:17:34.024770  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000029 (ops 140-144)
I20260812 06:17:34.024828  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000030 (ops 145-149)
I20260812 06:17:34.024891  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000031 (ops 150-154)
I20260812 06:17:34.024960  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000032 (ops 155-158)
I20260812 06:17:34.025031  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000033 (ops 159-163)
I20260812 06:17:34.025090  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000034 (ops 164-168)
I20260812 06:17:34.025147  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000035 (ops 169-173)
I20260812 06:17:34.025211  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000036 (ops 174-178)
I20260812 06:17:34.025274  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000037 (ops 179-183)
I20260812 06:17:34.025333  5601 log.cc:1079] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: Deleting log segment in path: /tmp/dist-test-taskFap3_v/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443617298-5135-0/minicluster-data/ts-0-root/wals/0fc3e34ff757486b858094e813c91a38/wal-000000038 (ops 184-188)
I20260812 06:17:34.057101  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: LogGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:34.057627  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38): 483 bytes on disk
I20260812 06:17:34.058218  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: UndoDeltaBlockGCOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.058947  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:34.083729  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.025s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5178,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:17:34.084268  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=2.188937
I20260812 06:17:34.096076  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.096757  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:34.273645  5135 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.938s	user 1.862s	sys 0.185s
I20260812 06:17:34.301074  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.204s	user 0.164s	sys 0.037s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020863,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14202,"lbm_reads_lt_1ms":771,"lbm_write_time_us":41979,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:17:34.301676  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38): perf score=14.095187
I20260812 06:17:34.338686  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: FlushDeltaMemStoresOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.037s	user 0.028s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17433,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:34.339346  5704 maintenance_manager.cc:419] P 5453a662951445358737e236a1bfd9d2: Scheduling MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38): perf score=1.000000
I20260812 06:17:34.358089  5135 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.001s	sys 0.000s
I20260812 06:17:34.358595  5135 tablet_server.cc:179] TabletServer@127.5.3.193:0 shutting down...
I20260812 06:17:34.461805  5601 maintenance_manager.cc:643] P 5453a662951445358737e236a1bfd9d2: MajorDeltaCompactionOp(0fc3e34ff757486b858094e813c91a38) complete. Timing: real 0.122s	user 0.077s	sys 0.042s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":532,"lbm_read_time_us":9958,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22654,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.462896  5135 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:34.463121  5135 tablet_replica.cc:333] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2: stopping tablet replica
I20260812 06:17:34.463269  5135 raft_consensus.cc:2243] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.463479  5135 raft_consensus.cc:2272] T 0fc3e34ff757486b858094e813c91a38 P 5453a662951445358737e236a1bfd9d2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.466918  5135 tablet_server.cc:196] TabletServer@127.5.3.193:0 shutdown complete.
I20260812 06:17:34.497464  5135 master.cc:562] Master@127.5.3.254:35783 shutting down...
I20260812 06:17:34.501336  5135 raft_consensus.cc:2243] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.501561  5135 raft_consensus.cc:2272] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.501662  5135 tablet_replica.cc:333] T 00000000000000000000000000000000 P deba1043b80a42b48453a8887e47e7e3: stopping tablet replica
I20260812 06:17:34.514237  5135 master.cc:584] Master@127.5.3.254:35783 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5474 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10975 ms total)

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