[==========] 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:18:27.691334  2438 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.97.190:39223
I20260812 06:18:27.692405  2438 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:18:27.693066  2438 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.700136  2445 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:18:27.700271  2438 server_base.cc:1061] running on GCE node
W20260812 06:18:27.700202  2448 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:27.700433  2446 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:18:27.700915  2438 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.701040  2438 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:18:27.701088  2438 hybrid_clock.cc:648] HybridClock initialized: now 1786515507701087 us; error 0 us; skew 500 ppm
I20260812 06:18:27.702922  2438 webserver.cc:533] Webserver started at http://127.2.97.190:33257/ using document root <none> and password file <none>
I20260812 06:18:27.703444  2438 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.703497  2438 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.703683  2438 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.705307  2438 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/master-0-root/instance:
uuid: "3f3da982fc2d417091b93a4fc7418b30"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-0kls"
I20260812 06:18:27.708788  2438 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:27.710907  2454 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:18:27.711915  2438 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:27.712010  2438 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/master-0-root
uuid: "3f3da982fc2d417091b93a4fc7418b30"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-0kls"
I20260812 06:18:27.712095  2438 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-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:18:27.736102  2438 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.736788  2438 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:18:27.736937  2438 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.745151  2438 rpc_server.cc:307] RPC server started. Bound to: 127.2.97.190:39223
I20260812 06:18:27.745178  2508 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.97.190:39223 every 8 connection(s)
I20260812 06:18:27.747628  2509 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:18:27.753297  2509 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30: Bootstrap starting.
I20260812 06:18:27.755709  2509 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.756604  2509 log.cc:826] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:27.758332  2509 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30: No bootstrap required, opened a new log
I20260812 06:18:27.761103  2509 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f3da982fc2d417091b93a4fc7418b30" member_type: VOTER }
I20260812 06:18:27.761283  2509 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.761336  2509 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3f3da982fc2d417091b93a4fc7418b30, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.762003  2509 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [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: "3f3da982fc2d417091b93a4fc7418b30" member_type: VOTER }
I20260812 06:18:27.762152  2509 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.762200  2509 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.762293  2509 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.763057  2509 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f3da982fc2d417091b93a4fc7418b30" member_type: VOTER }
I20260812 06:18:27.763456  2509 leader_election.cc:304] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [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: 3f3da982fc2d417091b93a4fc7418b30; no voters: 
I20260812 06:18:27.763731  2509 leader_election.cc:290] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.763883  2512 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.764146  2512 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 1 LEADER]: Becoming Leader. State: Replica: 3f3da982fc2d417091b93a4fc7418b30, State: Running, Role: LEADER
I20260812 06:18:27.764565  2512 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [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: "3f3da982fc2d417091b93a4fc7418b30" member_type: VOTER }
I20260812 06:18:27.764830  2509 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:27.766556  2513 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3f3da982fc2d417091b93a4fc7418b30" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f3da982fc2d417091b93a4fc7418b30" member_type: VOTER } }
I20260812 06:18:27.766737  2513 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.766578  2516 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3f3da982fc2d417091b93a4fc7418b30. Latest consensus state: current_term: 1 leader_uuid: "3f3da982fc2d417091b93a4fc7418b30" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f3da982fc2d417091b93a4fc7418b30" member_type: VOTER } }
I20260812 06:18:27.766825  2516 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.767200  2438 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:27.769129  2530 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:27.769210  2530 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:27.769284  2528 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:27.770097  2528 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:27.774852  2528 catalog_manager.cc:1383] Generated new cluster ID: fcaf8e8938e14d33add8561417a6a949
I20260812 06:18:27.774926  2528 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:27.781656  2528 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:27.782869  2528 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:27.792147  2528 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30: Generated new TSK 0
I20260812 06:18:27.792945  2528 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:27.799799  2438 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.802534  2536 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:18:27.802649  2539 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:27.802695  2537 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:18:27.802970  2438 server_base.cc:1061] running on GCE node
I20260812 06:18:27.803203  2438 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.803272  2438 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:18:27.803298  2438 hybrid_clock.cc:648] HybridClock initialized: now 1786515507803298 us; error 0 us; skew 500 ppm
I20260812 06:18:27.804224  2438 webserver.cc:533] Webserver started at http://127.2.97.129:41023/ using document root <none> and password file <none>
I20260812 06:18:27.804410  2438 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.804479  2438 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.804559  2438 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.804955  2438 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/instance:
uuid: "d1a5162ce3324b93a6de1e0585d286be"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-0kls"
I20260812 06:18:27.806588  2438 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:27.807587  2545 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:18:27.807832  2438 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:27.807899  2438 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root
uuid: "d1a5162ce3324b93a6de1e0585d286be"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-0kls"
I20260812 06:18:27.807986  2438 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-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:18:27.844314  2438 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.844835  2438 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.845386  2438 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:27.846390  2438 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:27.846462  2438 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.846529  2438 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:27.846575  2438 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.853433  2438 rpc_server.cc:307] RPC server started. Bound to: 127.2.97.129:44895
I20260812 06:18:27.853533  2616 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.97.129:44895 every 8 connection(s)
I20260812 06:18:27.868240  2617 heartbeater.cc:344] Connected to a master server at 127.2.97.190:39223
I20260812 06:18:27.868562  2617 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:27.869279  2617 heartbeater.cc:507] Master 127.2.97.190:39223 requested a full tablet report, sending...
I20260812 06:18:27.871119  2472 ts_manager.cc:194] Registered new tserver with Master: d1a5162ce3324b93a6de1e0585d286be (127.2.97.129:44895)
I20260812 06:18:27.871258  2438 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017049884s
I20260812 06:18:27.872701  2472 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56488
I20260812 06:18:27.881093  2472 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56502:
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:18:27.895738  2577 tablet_service.cc:1511] Processing CreateTablet for tablet c18945492c734339aa2f24697f016311 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c679885ccd554090a2cce455ee11081d]), partition=
I20260812 06:18:27.896253  2577 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c18945492c734339aa2f24697f016311. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.899153  2630 tablet_bootstrap.cc:492] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Bootstrap starting.
I20260812 06:18:27.900233  2630 tablet_bootstrap.cc:654] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.901428  2630 tablet_bootstrap.cc:492] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: No bootstrap required, opened a new log
I20260812 06:18:27.901540  2630 ts_tablet_manager.cc:1403] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:27.902092  2630 raft_consensus.cc:359] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1a5162ce3324b93a6de1e0585d286be" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 44895 } }
I20260812 06:18:27.902199  2630 raft_consensus.cc:385] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.902225  2630 raft_consensus.cc:740] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d1a5162ce3324b93a6de1e0585d286be, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.902391  2630 consensus_queue.cc:260] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [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: "d1a5162ce3324b93a6de1e0585d286be" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 44895 } }
I20260812 06:18:27.902469  2630 raft_consensus.cc:399] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.902513  2630 raft_consensus.cc:493] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.902565  2630 raft_consensus.cc:3060] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.903611  2630 raft_consensus.cc:515] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1a5162ce3324b93a6de1e0585d286be" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 44895 } }
I20260812 06:18:27.903767  2630 leader_election.cc:304] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [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: d1a5162ce3324b93a6de1e0585d286be; no voters: 
I20260812 06:18:27.904033  2630 leader_election.cc:290] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.904148  2632 raft_consensus.cc:2804] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.904378  2632 raft_consensus.cc:697] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 1 LEADER]: Becoming Leader. State: Replica: d1a5162ce3324b93a6de1e0585d286be, State: Running, Role: LEADER
I20260812 06:18:27.904417  2630 ts_tablet_manager.cc:1434] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:27.904527  2632 consensus_queue.cc:237] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [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: "d1a5162ce3324b93a6de1e0585d286be" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 44895 } }
I20260812 06:18:27.904840  2617 heartbeater.cc:499] Master 127.2.97.190:39223 was elected leader, sending a full tablet report...
I20260812 06:18:27.907634  2472 catalog_manager.cc:5719] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be reported cstate change: term changed from 0 to 1, leader changed from <none> to d1a5162ce3324b93a6de1e0585d286be (127.2.97.129). New cstate: current_term: 1 leader_uuid: "d1a5162ce3324b93a6de1e0585d286be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d1a5162ce3324b93a6de1e0585d286be" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 44895 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:27.972776  2438 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.018s	sys 0.008s
I20260812 06:18:28.104652  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushMRSOp(c18945492c734339aa2f24697f016311): perf score=15.086190
I20260812 06:18:28.272805  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushMRSOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.168s	user 0.144s	sys 0.020s Metrics: {"bytes_written":13210027,"cfile_init":1,"compiler_manager_pool.queue_time_us":233,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":285,"dirs.run_wall_time_us":1073,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40691,"lbm_writes_lt_1ms":679,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":163584,"thread_start_us":133,"threads_started":1,"update_count":1610}
I20260812 06:18:28.274004  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling LogGCOp(c18945492c734339aa2f24697f016311): free 20290830 bytes of WAL
I20260812 06:18:28.274290  2550 log_reader.cc:385] T c18945492c734339aa2f24697f016311: removed 2 log segments from log reader
I20260812 06:18:28.274348  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000001 (ops 1-6)
I20260812 06:18:28.274405  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000002 (ops 7-10)
I20260812 06:18:28.279546  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: LogGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:28.279987  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311): 12308958 bytes on disk
I20260812 06:18:28.280716  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.281112  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=5.165500
I20260812 06:18:28.302884  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.022s	user 0.013s	sys 0.008s Metrics: {"bytes_written":6769237,"delete_count":0,"lbm_write_time_us":9045,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:18:28.303359  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:28.471366  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.168s	user 0.109s	sys 0.056s Metrics: {"cfile_cache_miss":519,"cfile_cache_miss_bytes":24200421,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":10340,"lbm_reads_lt_1ms":551,"lbm_write_time_us":29026,"lbm_writes_lt_1ms":530,"mutex_wait_us":3,"peak_mem_usage":61542061,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":324,"threads_started":5,"update_count":2435}
I20260812 06:18:28.471920  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=11.118625
I20260812 06:18:28.511893  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.040s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12840814,"delete_count":0,"lbm_write_time_us":17141,"lbm_writes_lt_1ms":316,"reinsert_count":0,"update_count":1565}
I20260812 06:18:28.512463  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:28.528225  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.528805  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:28.653215  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.124s	user 0.091s	sys 0.033s Metrics: {"cfile_cache_miss":445,"cfile_cache_miss_bytes":21164636,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":8444,"lbm_reads_lt_1ms":485,"lbm_write_time_us":23429,"lbm_writes_lt_1ms":456,"mutex_wait_us":58,"peak_mem_usage":52263167,"reinsert_count":0,"update_count":2065}
I20260812 06:18:28.653874  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=10.126437
I20260812 06:18:28.695672  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.042s	user 0.017s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15841,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.696161  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:28.707597  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.708246  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:28.834228  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.126s	user 0.083s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":398,"lbm_read_time_us":9587,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23240,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22400,"update_count":2000}
I20260812 06:18:28.834851  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=10.126437
I20260812 06:18:28.875881  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.041s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13648,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.876489  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:28.891824  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.892261  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:29.059397  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.167s	user 0.110s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1023,"lbm_read_time_us":12257,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29021,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:18:29.060092  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=10.126437
I20260812 06:18:29.110136  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.050s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.110674  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:29.121515  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.122396  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:29.247000  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.124s	user 0.099s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1190,"lbm_read_time_us":9243,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24602,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:29.247529  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=10.126437
I20260812 06:18:29.284682  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.037s	user 0.006s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16285,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.285270  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:29.296028  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4095,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.296550  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:29.421720  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.125s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":340,"lbm_read_time_us":8722,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25226,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:18:29.422369  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=10.126437
I20260812 06:18:29.471939  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.049s	user 0.033s	sys 0.014s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16928,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.472602  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:29.489724  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.490370  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushMRSOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:29.531792  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushMRSOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.041s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1656,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1550,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:29.532696  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling LogGCOp(c18945492c734339aa2f24697f016311): free 108988524 bytes of WAL
I20260812 06:18:29.532930  2550 log_reader.cc:385] T c18945492c734339aa2f24697f016311: removed 11 log segments from log reader
I20260812 06:18:29.532989  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000003 (ops 11-15)
I20260812 06:18:29.533046  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000004 (ops 16-20)
I20260812 06:18:29.533098  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000005 (ops 21-25)
I20260812 06:18:29.533138  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000006 (ops 26-30)
I20260812 06:18:29.533176  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000007 (ops 31-34)
I20260812 06:18:29.533213  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000008 (ops 35-39)
I20260812 06:18:29.533257  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000009 (ops 40-44)
I20260812 06:18:29.533291  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000010 (ops 45-49)
I20260812 06:18:29.533334  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000011 (ops 50-54)
I20260812 06:18:29.533370  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000012 (ops 55-59)
I20260812 06:18:29.533406  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000013 (ops 60-64)
I20260812 06:18:29.560369  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: LogGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:29.560876  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:29.577174  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.577672  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311): 463 bytes on disk
I20260812 06:18:29.578157  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.578641  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:29.589413  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.590278  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:29.795570  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.205s	user 0.145s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":197,"lbm_read_time_us":14794,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33393,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:29.796227  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:29.863549  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.067s	user 0.019s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.864020  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:29.875376  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.876158  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:30.057116  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.181s	user 0.113s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":558,"lbm_read_time_us":13068,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30423,"lbm_writes_lt_1ms":543,"mutex_wait_us":301,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:18:30.057890  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:30.122359  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.064s	user 0.024s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24489,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.122968  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:30.133766  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.134354  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:30.330027  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.195s	user 0.133s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":14773,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30908,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:30.330641  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:30.398689  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.068s	user 0.052s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26212,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.399318  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:30.411298  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.412011  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:30.591096  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.179s	user 0.127s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":13366,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31639,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25088,"update_count":2500}
I20260812 06:18:30.591915  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=11.118625
I20260812 06:18:30.623620  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.031s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13993,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.624193  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:30.642927  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5992,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.643420  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:30.807199  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.164s	user 0.099s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":9417,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24211,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:18:30.807751  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:30.856650  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.048s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20908,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.857267  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:30.873615  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.874274  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:31.031036  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.157s	user 0.124s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":10708,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30818,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2500}
I20260812 06:18:31.031792  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=11.118625
I20260812 06:18:31.069123  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.037s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16928,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.069710  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:31.083930  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5869,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.084496  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushMRSOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:31.142150  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushMRSOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.057s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":133,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2359,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:31.142962  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling LogGCOp(c18945492c734339aa2f24697f016311): free 124257243 bytes of WAL
I20260812 06:18:31.143213  2550 log_reader.cc:385] T c18945492c734339aa2f24697f016311: removed 12 log segments from log reader
I20260812 06:18:31.143283  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000014 (ops 65-69)
I20260812 06:18:31.143335  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000015 (ops 70-74)
I20260812 06:18:31.143395  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000016 (ops 75-79)
I20260812 06:18:31.143440  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000017 (ops 80-84)
I20260812 06:18:31.143481  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000018 (ops 85-89)
I20260812 06:18:31.143520  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000019 (ops 90-94)
I20260812 06:18:31.143561  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000020 (ops 95-99)
I20260812 06:18:31.143599  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000021 (ops 100-104)
I20260812 06:18:31.143639  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000022 (ops 105-109)
I20260812 06:18:31.143698  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000023 (ops 110-114)
I20260812 06:18:31.143738  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000024 (ops 115-118)
I20260812 06:18:31.143784  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000025 (ops 119-123)
I20260812 06:18:31.173157  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: LogGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:31.173604  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311): 482 bytes on disk
I20260812 06:18:31.174106  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.174628  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=7.149875
I20260812 06:18:31.199908  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.025s	user 0.023s	sys 0.000s Metrics: {"bytes_written":9066585,"delete_count":0,"lbm_write_time_us":10175,"lbm_writes_lt_1ms":224,"reinsert_count":0,"update_count":1105}
I20260812 06:18:31.200685  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling LogGCOp(c18945492c734339aa2f24697f016311): free 8767123 bytes of WAL
I20260812 06:18:31.201007  2550 log_reader.cc:385] T c18945492c734339aa2f24697f016311: removed 1 log segments from log reader
I20260812 06:18:31.201054  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000026 (ops 124-128)
I20260812 06:18:31.203630  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: LogGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:31.204080  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:31.220619  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:31.221135  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:31.411885  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.191s	user 0.134s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938756,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":849,"lbm_read_time_us":12651,"lbm_reads_lt_1ms":766,"lbm_write_time_us":38702,"lbm_writes_lt_1ms":743,"mutex_wait_us":31,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:31.412842  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=15.087375
I20260812 06:18:31.466176  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.052s	user 0.041s	sys 0.011s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":24207,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:31.466723  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:31.489619  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.023s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5580,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.490147  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:31.500902  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.501683  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:31.685817  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.184s	user 0.171s	sys 0.012s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836244,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1375,"lbm_read_time_us":12626,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39374,"lbm_writes_lt_1ms":643,"mutex_wait_us":350,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:18:31.686403  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:31.734158  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.048s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20017,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.734927  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:31.749620  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.750237  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:31.919201  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.169s	user 0.095s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":9994,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29729,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:31.920037  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:31.986855  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.067s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19511,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.987377  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:31.998095  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.998814  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:32.185992  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.187s	user 0.117s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":648,"lbm_read_time_us":12255,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33884,"lbm_writes_lt_1ms":543,"mutex_wait_us":97,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2500}
I20260812 06:18:32.188627  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:32.246780  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.058s	user 0.022s	sys 0.035s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":26439,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.247334  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:32.260933  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.261869  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:32.429708  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.168s	user 0.114s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733727,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":516,"lbm_read_time_us":11634,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30556,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:32.430467  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=14.095187
I20260812 06:18:32.494048  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.063s	user 0.032s	sys 0.030s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24152,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.494616  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=2.188937
I20260812 06:18:32.505295  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.505937  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushMRSOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:32.534936  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushMRSOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1623,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1388,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:32.535801  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311): 448 bytes on disk
I20260812 06:18:32.536288  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: UndoDeltaBlockGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.536882  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:32.705086  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.168s	user 0.148s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1018,"lbm_read_time_us":13042,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28290,"lbm_writes_lt_1ms":543,"mutex_wait_us":285,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":59008,"update_count":2500}
I20260812 06:18:32.705646  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling LogGCOp(c18945492c734339aa2f24697f016311): free 115490369 bytes of WAL
I20260812 06:18:32.705955  2550 log_reader.cc:385] T c18945492c734339aa2f24697f016311: removed 11 log segments from log reader
I20260812 06:18:32.706034  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000027 (ops 129-133)
I20260812 06:18:32.706099  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000028 (ops 134-138)
I20260812 06:18:32.706163  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000029 (ops 139-143)
I20260812 06:18:32.706238  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000030 (ops 144-148)
I20260812 06:18:32.706295  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000031 (ops 149-153)
I20260812 06:18:32.706362  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000032 (ops 154-158)
I20260812 06:18:32.706401  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000033 (ops 159-163)
I20260812 06:18:32.706446  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000034 (ops 164-168)
I20260812 06:18:32.706513  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000035 (ops 169-172)
I20260812 06:18:32.706553  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000036 (ops 173-177)
I20260812 06:18:32.706619  2550 log.cc:1079] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/c18945492c734339aa2f24697f016311/wal-000000037 (ops 178-182)
I20260812 06:18:32.735862  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: LogGCOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.030s	user 0.003s	sys 0.024s Metrics: {}
I20260812 06:18:32.736408  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=15.087375
I20260812 06:18:32.806834  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.070s	user 0.033s	sys 0.030s Metrics: {"bytes_written":16820152,"delete_count":0,"lbm_write_time_us":23588,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:32.807514  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=6.157687
I20260812 06:18:32.827875  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.020s	user 0.010s	sys 0.008s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8284,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:32.828419  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311): perf score=1.000000
I20260812 06:18:32.969822  2438 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.997s	user 1.799s	sys 0.213s
I20260812 06:18:33.016821  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: MajorDeltaCompactionOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.188s	user 0.122s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836145,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":16069,"lbm_reads_lt_1ms":668,"lbm_write_time_us":32867,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:33.017347  2619 maintenance_manager.cc:419] P d1a5162ce3324b93a6de1e0585d286be: Scheduling FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311): perf score=10.126437
I20260812 06:18:33.036402  2438 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.066s	user 0.001s	sys 0.000s
I20260812 06:18:33.037062  2438 tablet_server.cc:179] TabletServer@127.2.97.129:0 shutting down...
I20260812 06:18:33.053696  2550 maintenance_manager.cc:643] P d1a5162ce3324b93a6de1e0585d286be: FlushDeltaMemStoresOp(c18945492c734339aa2f24697f016311) complete. Timing: real 0.036s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16018,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.054425  2438 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:33.054831  2438 tablet_replica.cc:333] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be: stopping tablet replica
I20260812 06:18:33.055058  2438 raft_consensus.cc:2243] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.064086  2438 raft_consensus.cc:2272] T c18945492c734339aa2f24697f016311 P d1a5162ce3324b93a6de1e0585d286be [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.081683  2438 tablet_server.cc:196] TabletServer@127.2.97.129:0 shutdown complete.
I20260812 06:18:33.086823  2438 master.cc:562] Master@127.2.97.190:39223 shutting down...
I20260812 06:18:33.090472  2438 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.090647  2438 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.090700  2438 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3f3da982fc2d417091b93a4fc7418b30: stopping tablet replica
I20260812 06:18:33.103432  2438 master.cc:584] Master@127.2.97.190:39223 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5509 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:33.200448  2438 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.97.190:40727
I20260812 06:18:33.200953  2438 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.203598  2652 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:18:33.203645  2438 server_base.cc:1061] running on GCE node
W20260812 06:18:33.203651  2654 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.203604  2651 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:18:33.204129  2438 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.204171  2438 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:18:33.204186  2438 hybrid_clock.cc:648] HybridClock initialized: now 1786515513204187 us; error 0 us; skew 500 ppm
I20260812 06:18:33.205063  2438 webserver.cc:533] Webserver started at http://127.2.97.190:46549/ using document root <none> and password file <none>
I20260812 06:18:33.205204  2438 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.205262  2438 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.205317  2438 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.205655  2438 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/master-0-root/instance:
uuid: "38839e329004436db24b43a52158e5e7"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-0kls"
I20260812 06:18:33.207307  2438 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:33.208241  2660 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:18:33.208525  2438 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:33.208590  2438 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/master-0-root
uuid: "38839e329004436db24b43a52158e5e7"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-0kls"
I20260812 06:18:33.208689  2438 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-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:18:33.213442  2438 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.213877  2438 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.218107  2438 rpc_server.cc:307] RPC server started. Bound to: 127.2.97.190:40727
I20260812 06:18:33.220997  2718 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:18:33.220999  2717 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.97.190:40727 every 8 connection(s)
I20260812 06:18:33.227813  2718 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7: Bootstrap starting.
I20260812 06:18:33.228713  2718 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.229884  2718 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7: No bootstrap required, opened a new log
I20260812 06:18:33.230329  2718 raft_consensus.cc:359] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38839e329004436db24b43a52158e5e7" member_type: VOTER }
I20260812 06:18:33.230418  2718 raft_consensus.cc:385] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.230475  2718 raft_consensus.cc:740] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 38839e329004436db24b43a52158e5e7, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.230659  2718 consensus_queue.cc:260] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [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: "38839e329004436db24b43a52158e5e7" member_type: VOTER }
I20260812 06:18:33.230733  2718 raft_consensus.cc:399] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.230791  2718 raft_consensus.cc:493] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.230849  2718 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.231571  2718 raft_consensus.cc:515] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38839e329004436db24b43a52158e5e7" member_type: VOTER }
I20260812 06:18:33.231726  2718 leader_election.cc:304] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [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: 38839e329004436db24b43a52158e5e7; no voters: 
I20260812 06:18:33.231962  2718 leader_election.cc:290] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.232103  2724 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.232316  2724 raft_consensus.cc:697] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 1 LEADER]: Becoming Leader. State: Replica: 38839e329004436db24b43a52158e5e7, State: Running, Role: LEADER
I20260812 06:18:33.232443  2718 sys_catalog.cc:565] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:33.232470  2724 consensus_queue.cc:237] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [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: "38839e329004436db24b43a52158e5e7" member_type: VOTER }
I20260812 06:18:33.232957  2725 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "38839e329004436db24b43a52158e5e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38839e329004436db24b43a52158e5e7" member_type: VOTER } }
I20260812 06:18:33.233052  2725 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.233012  2726 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 38839e329004436db24b43a52158e5e7. Latest consensus state: current_term: 1 leader_uuid: "38839e329004436db24b43a52158e5e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38839e329004436db24b43a52158e5e7" member_type: VOTER } }
I20260812 06:18:33.233300  2726 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.233390  2730 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:33.234493  2730 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:33.234711  2438 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:33.236382  2730 catalog_manager.cc:1383] Generated new cluster ID: 1fba592288e548f69c2e351364cb42bc
I20260812 06:18:33.236440  2730 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:33.248157  2730 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:33.248749  2730 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:33.255178  2730 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7: Generated new TSK 0
I20260812 06:18:33.255371  2730 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:33.267410  2438 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.269627  2742 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:18:33.269779  2438 server_base.cc:1061] running on GCE node
W20260812 06:18:33.269912  2743 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:18:33.269765  2745 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:18:33.270164  2438 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.270241  2438 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:18:33.270278  2438 hybrid_clock.cc:648] HybridClock initialized: now 1786515513270277 us; error 0 us; skew 500 ppm
I20260812 06:18:33.271152  2438 webserver.cc:533] Webserver started at http://127.2.97.129:44445/ using document root <none> and password file <none>
I20260812 06:18:33.271358  2438 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.271435  2438 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.271519  2438 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.271986  2438 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/instance:
uuid: "5338f135bfde41059175616594bd18c9"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-0kls"
I20260812 06:18:33.273525  2438 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:33.274663  2750 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:18:33.274935  2438 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.275023  2438 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root
uuid: "5338f135bfde41059175616594bd18c9"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-0kls"
I20260812 06:18:33.275111  2438 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-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:18:33.297254  2438 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.297699  2438 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.298080  2438 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:33.298558  2438 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:33.298619  2438 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.298677  2438 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:33.298733  2438 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.303158  2438 rpc_server.cc:307] RPC server started. Bound to: 127.2.97.129:33719
I20260812 06:18:33.304128  2827 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.97.129:33719 every 8 connection(s)
I20260812 06:18:33.316221  2828 heartbeater.cc:344] Connected to a master server at 127.2.97.190:40727
I20260812 06:18:33.316381  2828 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:33.316668  2828 heartbeater.cc:507] Master 127.2.97.190:40727 requested a full tablet report, sending...
I20260812 06:18:33.317445  2680 ts_manager.cc:194] Registered new tserver with Master: 5338f135bfde41059175616594bd18c9 (127.2.97.129:33719)
I20260812 06:18:33.318396  2680 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40718
I20260812 06:18:33.318429  2438 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014314026s
I20260812 06:18:33.326223  2680 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40720:
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:18:33.335800  2785 tablet_service.cc:1511] Processing CreateTablet for tablet 9b6980dae729432caf861cb638adb6dd (DEFAULT_TABLE table=heavy-update-compaction-test [id=faaadb4a8abd40fdbcdbf86c6ced842a]), partition=
I20260812 06:18:33.336153  2785 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9b6980dae729432caf861cb638adb6dd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:33.338145  2840 tablet_bootstrap.cc:492] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Bootstrap starting.
I20260812 06:18:33.339118  2840 tablet_bootstrap.cc:654] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.340461  2840 tablet_bootstrap.cc:492] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: No bootstrap required, opened a new log
I20260812 06:18:33.340570  2840 ts_tablet_manager.cc:1403] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:33.341091  2840 raft_consensus.cc:359] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5338f135bfde41059175616594bd18c9" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 33719 } }
I20260812 06:18:33.341200  2840 raft_consensus.cc:385] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.341256  2840 raft_consensus.cc:740] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5338f135bfde41059175616594bd18c9, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.341405  2840 consensus_queue.cc:260] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [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: "5338f135bfde41059175616594bd18c9" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 33719 } }
I20260812 06:18:33.341497  2840 raft_consensus.cc:399] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.341542  2840 raft_consensus.cc:493] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.341596  2840 raft_consensus.cc:3060] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.342415  2840 raft_consensus.cc:515] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5338f135bfde41059175616594bd18c9" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 33719 } }
I20260812 06:18:33.342573  2840 leader_election.cc:304] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [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: 5338f135bfde41059175616594bd18c9; no voters: 
I20260812 06:18:33.342806  2840 leader_election.cc:290] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.342960  2842 raft_consensus.cc:2804] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.343164  2840 ts_tablet_manager.cc:1434] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:33.343197  2828 heartbeater.cc:499] Master 127.2.97.190:40727 was elected leader, sending a full tablet report...
I20260812 06:18:33.343268  2842 raft_consensus.cc:697] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 1 LEADER]: Becoming Leader. State: Replica: 5338f135bfde41059175616594bd18c9, State: Running, Role: LEADER
I20260812 06:18:33.343438  2842 consensus_queue.cc:237] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [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: "5338f135bfde41059175616594bd18c9" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 33719 } }
I20260812 06:18:33.344851  2680 catalog_manager.cc:5719] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5338f135bfde41059175616594bd18c9 (127.2.97.129). New cstate: current_term: 1 leader_uuid: "5338f135bfde41059175616594bd18c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5338f135bfde41059175616594bd18c9" member_type: VOTER last_known_addr { host: "127.2.97.129" port: 33719 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:33.403775  2438 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.014s	sys 0.008s
I20260812 06:18:33.554620  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushMRSOp(9b6980dae729432caf861cb638adb6dd): perf score=19.054940
I20260812 06:18:33.715643  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushMRSOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.161s	user 0.110s	sys 0.049s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":122,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":896,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38644,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1550}
I20260812 06:18:33.716300  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling LogGCOp(9b6980dae729432caf861cb638adb6dd): free 20743831 bytes of WAL
I20260812 06:18:33.716542  2758 log_reader.cc:385] T 9b6980dae729432caf861cb638adb6dd: removed 2 log segments from log reader
I20260812 06:18:33.716607  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000001 (ops 1-6)
I20260812 06:18:33.716661  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000002 (ops 7-11)
I20260812 06:18:33.721089  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: LogGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:33.721491  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd): 16411394 bytes on disk
I20260812 06:18:33.722035  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.722687  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:33.734462  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.734989  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:33.878230  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.143s	user 0.100s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1426,"lbm_read_time_us":9424,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24437,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":357,"threads_started":5,"update_count":2000}
I20260812 06:18:33.878825  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=11.118625
I20260812 06:18:33.923298  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.044s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16091,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.924000  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:33.946760  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.022s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.947220  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:33.956946  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3623,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.957419  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:34.144555  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.187s	user 0.132s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":694,"lbm_read_time_us":14226,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29802,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:34.145123  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=14.095187
I20260812 06:18:34.202689  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.057s	user 0.022s	sys 0.034s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21065,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.203188  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:34.213954  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.214412  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:34.414904  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.200s	user 0.128s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":311,"lbm_read_time_us":12852,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31799,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27136,"update_count":2500}
I20260812 06:18:34.415567  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=14.095187
I20260812 06:18:34.482844  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.067s	user 0.030s	sys 0.034s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25225,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.483398  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:34.493947  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.494498  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:34.677983  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.183s	user 0.131s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":12763,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28331,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:34.678583  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=14.095187
I20260812 06:18:34.729872  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.051s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20385,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.730329  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:34.752944  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.022s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.753507  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:34.949616  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.196s	user 0.127s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":494,"lbm_read_time_us":14874,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29479,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:34.950382  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=14.095187
I20260812 06:18:35.004309  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.054s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21018,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.004890  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:35.032622  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.028s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.033106  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:35.053633  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.054154  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushMRSOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:35.090441  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushMRSOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.036s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1581,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1742,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:35.091032  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling LogGCOp(9b6980dae729432caf861cb638adb6dd): free 124257288 bytes of WAL
I20260812 06:18:35.091261  2758 log_reader.cc:385] T 9b6980dae729432caf861cb638adb6dd: removed 12 log segments from log reader
I20260812 06:18:35.091301  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000003 (ops 12-16)
I20260812 06:18:35.091332  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000004 (ops 17-20)
I20260812 06:18:35.091393  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000005 (ops 21-25)
I20260812 06:18:35.091426  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000006 (ops 26-30)
I20260812 06:18:35.091468  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000007 (ops 31-35)
I20260812 06:18:35.091527  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000008 (ops 36-40)
I20260812 06:18:35.091557  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000009 (ops 41-45)
I20260812 06:18:35.091596  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000010 (ops 46-50)
I20260812 06:18:35.091635  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000011 (ops 51-55)
I20260812 06:18:35.091676  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000012 (ops 56-60)
I20260812 06:18:35.091717  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000013 (ops 61-65)
I20260812 06:18:35.091758  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000014 (ops 66-70)
I20260812 06:18:35.119885  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: LogGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:35.120530  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=3.181125
I20260812 06:18:35.138091  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.017s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:35.138545  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd): 472 bytes on disk
I20260812 06:18:35.138933  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd) 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:18:35.139359  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:35.148948  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3599,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.149407  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:35.401382  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.252s	user 0.183s	sys 0.064s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":612,"lbm_read_time_us":17978,"lbm_reads_lt_1ms":875,"lbm_write_time_us":42511,"lbm_writes_lt_1ms":843,"mutex_wait_us":306,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":80,"threads_started":1,"update_count":4000}
I20260812 06:18:35.402159  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=18.063937
I20260812 06:18:35.467757  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.065s	user 0.045s	sys 0.007s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":23220,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.468461  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:35.492928  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5625,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.493432  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:35.503979  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.504469  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:35.696094  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.191s	user 0.135s	sys 0.056s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979638,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":525,"lbm_read_time_us":12255,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42551,"lbm_writes_lt_1ms":743,"mutex_wait_us":26,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":42240,"update_count":3500}
I20260812 06:18:35.696796  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=15.087375
I20260812 06:18:35.751695  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.055s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":24577,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:35.752418  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:35.770332  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5933,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.770872  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:35.942956  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.172s	user 0.122s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774674,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":508,"lbm_read_time_us":8993,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32451,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:18:35.947701  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=14.095187
I20260812 06:18:35.996575  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.049s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21647,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.997076  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:36.027761  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.030s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7684,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.028424  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:36.206353  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.178s	user 0.128s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":13364,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29230,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:18:36.207137  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=16.079562
I20260812 06:18:36.273322  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.066s	user 0.036s	sys 0.020s Metrics: {"bytes_written":18214962,"delete_count":0,"lbm_write_time_us":30720,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":443,"reinsert_count":0,"update_count":2220}
I20260812 06:18:36.273857  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=5.165500
I20260812 06:18:36.295282  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.021s	user 0.005s	sys 0.013s Metrics: {"bytes_written":6400021,"delete_count":0,"lbm_write_time_us":7565,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:18:36.295830  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:36.495707  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.200s	user 0.107s	sys 0.088s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":13380,"lbm_reads_lt_1ms":668,"lbm_write_time_us":32977,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:36.496420  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=18.063937
I20260812 06:18:36.564762  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.068s	user 0.032s	sys 0.017s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24033,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.565317  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:36.575984  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.576871  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushMRSOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:36.608944  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushMRSOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1582,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1418,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:36.609638  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling LogGCOp(9b6980dae729432caf861cb638adb6dd): free 121006391 bytes of WAL
I20260812 06:18:36.609902  2758 log_reader.cc:385] T 9b6980dae729432caf861cb638adb6dd: removed 12 log segments from log reader
I20260812 06:18:36.609961  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000015 (ops 71-75)
I20260812 06:18:36.610013  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000016 (ops 76-80)
I20260812 06:18:36.610059  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000017 (ops 81-85)
I20260812 06:18:36.610102  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000018 (ops 86-90)
I20260812 06:18:36.610139  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000019 (ops 91-95)
I20260812 06:18:36.610179  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000020 (ops 96-100)
I20260812 06:18:36.610220  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000021 (ops 101-104)
I20260812 06:18:36.610260  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000022 (ops 105-109)
I20260812 06:18:36.610301  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000023 (ops 110-114)
I20260812 06:18:36.610337  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000024 (ops 115-119)
I20260812 06:18:36.610378  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000025 (ops 120-124)
I20260812 06:18:36.610416  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000026 (ops 125-129)
I20260812 06:18:36.638226  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: LogGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.028s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:36.638752  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd): 482 bytes on disk
I20260812 06:18:36.639365  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.639981  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=4.173312
I20260812 06:18:36.653249  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":5359,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:18:36.653700  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling LogGCOp(9b6980dae729432caf861cb638adb6dd): free 12018006 bytes of WAL
I20260812 06:18:36.653923  2758 log_reader.cc:385] T 9b6980dae729432caf861cb638adb6dd: removed 1 log segments from log reader
I20260812 06:18:36.653967  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000027 (ops 130-134)
I20260812 06:18:36.656345  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: LogGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:36.656649  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=1.196750
I20260812 06:18:36.669672  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4111,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:18:36.670158  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:36.907073  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.237s	user 0.181s	sys 0.056s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082138,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":261,"lbm_read_time_us":18903,"lbm_reads_lt_1ms":870,"lbm_write_time_us":41855,"lbm_writes_lt_1ms":843,"mutex_wait_us":52,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":41088,"thread_start_us":78,"threads_started":1,"update_count":4000}
I20260812 06:18:36.908021  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=18.063937
I20260812 06:18:36.983479  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.075s	user 0.046s	sys 0.017s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29338,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.984004  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=6.157687
I20260812 06:18:37.010181  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.026s	user 0.015s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10223,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:37.010784  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:37.200460  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.189s	user 0.141s	sys 0.047s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32979516,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":15191,"lbm_reads_lt_1ms":764,"lbm_write_time_us":40482,"lbm_writes_lt_1ms":743,"mutex_wait_us":32,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:18:37.201227  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=15.087375
I20260812 06:18:37.243340  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.042s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":18097,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:37.243892  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:37.259217  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5001,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.259739  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:37.431874  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.172s	user 0.141s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":548,"lbm_read_time_us":10701,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33008,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:18:37.435948  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=14.095187
I20260812 06:18:37.493103  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.057s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19934,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.493616  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:37.509505  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.016s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.510288  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:37.691525  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.181s	user 0.132s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":12190,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30711,"lbm_writes_lt_1ms":543,"mutex_wait_us":281,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:37.692117  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=14.095187
I20260812 06:18:37.745833  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.054s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23862,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.746615  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:37.902072  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.155s	user 0.101s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":590,"lbm_read_time_us":11601,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26481,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:37.902748  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=11.118625
I20260812 06:18:37.946547  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.044s	user 0.015s	sys 0.028s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18661,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:37.947094  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:37.968252  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.021s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5397,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.968742  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:37.979228  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.979743  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushMRSOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:38.019784  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushMRSOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.040s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1536,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2471,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:38.020534  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling LogGCOp(9b6980dae729432caf861cb638adb6dd): free 108082636 bytes of WAL
I20260812 06:18:38.020776  2758 log_reader.cc:385] T 9b6980dae729432caf861cb638adb6dd: removed 11 log segments from log reader
I20260812 06:18:38.020820  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000028 (ops 135-139)
I20260812 06:18:38.020849  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000029 (ops 140-144)
I20260812 06:18:38.020905  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000030 (ops 145-148)
I20260812 06:18:38.020942  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000031 (ops 149-153)
I20260812 06:18:38.021004  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000032 (ops 154-158)
I20260812 06:18:38.021036  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000033 (ops 159-162)
I20260812 06:18:38.021071  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000034 (ops 163-167)
I20260812 06:18:38.021107  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000035 (ops 168-172)
I20260812 06:18:38.021147  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000036 (ops 173-176)
I20260812 06:18:38.021185  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000037 (ops 177-181)
I20260812 06:18:38.021209  2758 log.cc:1079] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: Deleting log segment in path: /tmp/dist-test-task2HRlhX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507680314-2438-0/minicluster-data/ts-0-root/wals/9b6980dae729432caf861cb638adb6dd/wal-000000038 (ops 182-186)
I20260812 06:18:38.045313  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: LogGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:38.045853  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd): 447 bytes on disk
I20260812 06:18:38.046514  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: UndoDeltaBlockGCOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.047194  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:38.069391  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.022s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.069950  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=2.188937
I20260812 06:18:38.080701  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.081215  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd): perf score=1.000000
I20260812 06:18:38.305090  2438 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.901s	user 1.819s	sys 0.150s
I20260812 06:18:38.319950  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: MajorDeltaCompactionOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.239s	user 0.151s	sys 0.087s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979861,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":540,"lbm_read_time_us":15202,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41462,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":21120,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:18:38.320751  2829 maintenance_manager.cc:419] P 5338f135bfde41059175616594bd18c9: Scheduling FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd): perf score=18.063937
I20260812 06:18:38.357697  2438 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.052s	user 0.002s	sys 0.000s
I20260812 06:18:38.358314  2438 tablet_server.cc:179] TabletServer@127.2.97.129:0 shutting down...
I20260812 06:18:38.373343  2758 maintenance_manager.cc:643] P 5338f135bfde41059175616594bd18c9: FlushDeltaMemStoresOp(9b6980dae729432caf861cb638adb6dd) complete. Timing: real 0.052s	user 0.041s	sys 0.008s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23743,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:38.374022  2438 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:38.374226  2438 tablet_replica.cc:333] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9: stopping tablet replica
I20260812 06:18:38.374416  2438 raft_consensus.cc:2243] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.374615  2438 raft_consensus.cc:2272] T 9b6980dae729432caf861cb638adb6dd P 5338f135bfde41059175616594bd18c9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.388316  2438 tablet_server.cc:196] TabletServer@127.2.97.129:0 shutdown complete.
I20260812 06:18:38.391461  2438 master.cc:562] Master@127.2.97.190:40727 shutting down...
I20260812 06:18:38.394938  2438 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.395136  2438 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.395229  2438 tablet_replica.cc:333] T 00000000000000000000000000000000 P 38839e329004436db24b43a52158e5e7: stopping tablet replica
I20260812 06:18:38.407459  2438 master.cc:584] Master@127.2.97.190:40727 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5301 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10812 ms total)

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