[==========] 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:16:36.993415 32716 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.243.62:35479
I20260812 06:16:36.994485 32716 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:16:36.995146 32716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:37.001665 32727 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:16:37.001727 32716 server_base.cc:1061] running on GCE node
W20260812 06:16:37.001684 32724 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:16:37.001964 32723 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:16:37.002504 32716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:37.002609 32716 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:16:37.002636 32716 hybrid_clock.cc:648] HybridClock initialized: now 1786515397002635 us; error 0 us; skew 500 ppm
I20260812 06:16:37.004384 32716 webserver.cc:533] Webserver started at http://127.31.243.62:45869/ using document root <none> and password file <none>
I20260812 06:16:37.004877 32716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:37.004928 32716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:37.005110 32716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:37.007174 32716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/master-0-root/instance:
uuid: "4f0f9a7b57734999ab086aeab95c8b2a"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-7c35"
I20260812 06:16:37.010720 32716 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:16:37.012842 32732 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:16:37.013818 32716 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:37.013942 32716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/master-0-root
uuid: "4f0f9a7b57734999ab086aeab95c8b2a"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-7c35"
I20260812 06:16:37.014038 32716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-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:16:37.035120 32716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:37.035840 32716 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:16:37.036029 32716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:37.043751 32716 rpc_server.cc:307] RPC server started. Bound to: 127.31.243.62:35479
I20260812 06:16:37.043762   330 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.243.62:35479 every 8 connection(s)
I20260812 06:16:37.045897   331 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:16:37.051337   331 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a: Bootstrap starting.
I20260812 06:16:37.053532   331 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:37.054409   331 log.cc:826] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:37.056023   331 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a: No bootstrap required, opened a new log
I20260812 06:16:37.058627   331 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f0f9a7b57734999ab086aeab95c8b2a" member_type: VOTER }
I20260812 06:16:37.058779   331 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:37.058930   331 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4f0f9a7b57734999ab086aeab95c8b2a, State: Initialized, Role: FOLLOWER
I20260812 06:16:37.059532   331 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [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: "4f0f9a7b57734999ab086aeab95c8b2a" member_type: VOTER }
I20260812 06:16:37.059697   331 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:37.059767   331 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:37.059927   331 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:37.060722   331 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f0f9a7b57734999ab086aeab95c8b2a" member_type: VOTER }
I20260812 06:16:37.061147   331 leader_election.cc:304] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [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: 4f0f9a7b57734999ab086aeab95c8b2a; no voters: 
I20260812 06:16:37.061465   331 leader_election.cc:290] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:37.061614   334 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:37.061885   334 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 1 LEADER]: Becoming Leader. State: Replica: 4f0f9a7b57734999ab086aeab95c8b2a, State: Running, Role: LEADER
I20260812 06:16:37.062311   334 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [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: "4f0f9a7b57734999ab086aeab95c8b2a" member_type: VOTER }
I20260812 06:16:37.062426   331 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:37.064105   336 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4f0f9a7b57734999ab086aeab95c8b2a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f0f9a7b57734999ab086aeab95c8b2a" member_type: VOTER } }
I20260812 06:16:37.064209   337 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4f0f9a7b57734999ab086aeab95c8b2a. Latest consensus state: current_term: 1 leader_uuid: "4f0f9a7b57734999ab086aeab95c8b2a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f0f9a7b57734999ab086aeab95c8b2a" member_type: VOTER } }
I20260812 06:16:37.064215   336 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:37.064303   337 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:37.064644   348 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:37.064997 32716 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:37.067181   348 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:37.071689   348 catalog_manager.cc:1383] Generated new cluster ID: 6cfb7bca24ee417c94dafeeedfb79551
I20260812 06:16:37.071760   348 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:37.083411   348 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:37.084211   348 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:37.091279   348 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a: Generated new TSK 0
I20260812 06:16:37.091850   348 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:37.097610 32716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:37.100229   359 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:16:37.100325   362 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:16:37.100337   360 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:16:37.100675 32716 server_base.cc:1061] running on GCE node
I20260812 06:16:37.100832 32716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:37.100868 32716 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:16:37.100883 32716 hybrid_clock.cc:648] HybridClock initialized: now 1786515397100883 us; error 0 us; skew 500 ppm
I20260812 06:16:37.101797 32716 webserver.cc:533] Webserver started at http://127.31.243.1:36839/ using document root <none> and password file <none>
I20260812 06:16:37.101987 32716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:37.102031 32716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:37.102121 32716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:37.102510 32716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/instance:
uuid: "f26c972b09d34c8a8b02605a0d3f4cfa"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-7c35"
I20260812 06:16:37.104019 32716 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:37.105046   369 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:16:37.105314 32716 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:37.105396 32716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root
uuid: "f26c972b09d34c8a8b02605a0d3f4cfa"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-7c35"
I20260812 06:16:37.105476 32716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-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:16:37.133777 32716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:37.134291 32716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:37.134789 32716 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:37.135672 32716 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:37.135748 32716 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.135825 32716 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:37.135871 32716 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.144991 32716 rpc_server.cc:307] RPC server started. Bound to: 127.31.243.1:39777
I20260812 06:16:37.145028   446 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.243.1:39777 every 8 connection(s)
I20260812 06:16:37.155606   447 heartbeater.cc:344] Connected to a master server at 127.31.243.62:35479
I20260812 06:16:37.155866   447 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:37.156332   447 heartbeater.cc:507] Master 127.31.243.62:35479 requested a full tablet report, sending...
I20260812 06:16:37.157745 32756 ts_manager.cc:194] Registered new tserver with Master: f26c972b09d34c8a8b02605a0d3f4cfa (127.31.243.1:39777)
I20260812 06:16:37.158041 32716 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0123802s
I20260812 06:16:37.159281 32756 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34440
I20260812 06:16:37.169190 32756 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34454:
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:16:37.183243   401 tablet_service.cc:1511] Processing CreateTablet for tablet dcdc13f42b1e4798ae387713b05a86f5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=05e5e237a8244fee9c547687532c5906]), partition=
I20260812 06:16:37.183712   401 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dcdc13f42b1e4798ae387713b05a86f5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:37.187258   459 tablet_bootstrap.cc:492] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Bootstrap starting.
I20260812 06:16:37.188079   459 tablet_bootstrap.cc:654] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:37.189141   459 tablet_bootstrap.cc:492] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: No bootstrap required, opened a new log
I20260812 06:16:37.189255   459 ts_tablet_manager.cc:1403] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:37.189752   459 raft_consensus.cc:359] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26c972b09d34c8a8b02605a0d3f4cfa" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 39777 } }
I20260812 06:16:37.189893   459 raft_consensus.cc:385] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:37.189976   459 raft_consensus.cc:740] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f26c972b09d34c8a8b02605a0d3f4cfa, State: Initialized, Role: FOLLOWER
I20260812 06:16:37.190181   459 consensus_queue.cc:260] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [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: "f26c972b09d34c8a8b02605a0d3f4cfa" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 39777 } }
I20260812 06:16:37.190354   459 raft_consensus.cc:399] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:37.190407   459 raft_consensus.cc:493] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:37.190469   459 raft_consensus.cc:3060] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:37.191284   459 raft_consensus.cc:515] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26c972b09d34c8a8b02605a0d3f4cfa" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 39777 } }
I20260812 06:16:37.191432   459 leader_election.cc:304] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [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: f26c972b09d34c8a8b02605a0d3f4cfa; no voters: 
I20260812 06:16:37.191681   459 leader_election.cc:290] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:37.191771   462 raft_consensus.cc:2804] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:37.191993   462 raft_consensus.cc:697] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 1 LEADER]: Becoming Leader. State: Replica: f26c972b09d34c8a8b02605a0d3f4cfa, State: Running, Role: LEADER
I20260812 06:16:37.192075   459 ts_tablet_manager.cc:1434] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:37.192176   462 consensus_queue.cc:237] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [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: "f26c972b09d34c8a8b02605a0d3f4cfa" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 39777 } }
I20260812 06:16:37.192356   447 heartbeater.cc:499] Master 127.31.243.62:35479 was elected leader, sending a full tablet report...
I20260812 06:16:37.195411 32756 catalog_manager.cc:5719] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa reported cstate change: term changed from 0 to 1, leader changed from <none> to f26c972b09d34c8a8b02605a0d3f4cfa (127.31.243.1). New cstate: current_term: 1 leader_uuid: "f26c972b09d34c8a8b02605a0d3f4cfa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26c972b09d34c8a8b02605a0d3f4cfa" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 39777 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:37.266197 32716 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.012s	sys 0.020s
I20260812 06:16:37.396106   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=19.054940
I20260812 06:16:37.611433   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.215s	user 0.170s	sys 0.032s Metrics: {"bytes_written":13948451,"cfile_init":1,"compiler_manager_pool.queue_time_us":193,"delete_count":0,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":969,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":57123,"lbm_writes_lt_1ms":797,"mutex_wait_us":2355,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":150912,"thread_start_us":127,"threads_started":1,"update_count":1700}
I20260812 06:16:37.612710   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling LogGCOp(dcdc13f42b1e4798ae387713b05a86f5): free 20743880 bytes of WAL
I20260812 06:16:37.613021   375 log_reader.cc:385] T dcdc13f42b1e4798ae387713b05a86f5: removed 2 log segments from log reader
I20260812 06:16:37.613087   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000001 (ops 1-6)
I20260812 06:16:37.613139   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000002 (ops 7-11)
I20260812 06:16:37.620285   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: LogGCOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:16:37.621166   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5): 16411393 bytes on disk
I20260812 06:16:37.622360   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.001s	user 0.000s	sys 0.001s Metrics: {"cfile_init":1,"lbm_read_time_us":202,"lbm_reads_lt_1ms":4}
I20260812 06:16:37.623096   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=5.165500
I20260812 06:16:37.648111   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.025s	user 0.010s	sys 0.014s Metrics: {"bytes_written":6564117,"delete_count":0,"lbm_write_time_us":10143,"lbm_writes_lt_1ms":163,"reinsert_count":0,"update_count":800}
I20260812 06:16:37.648602   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:37.831723   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.183s	user 0.119s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":931,"lbm_read_time_us":10199,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32924,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":315,"threads_started":5,"update_count":2500}
I20260812 06:16:37.832338   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:37.889379   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.057s	user 0.024s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26593,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:37.889809   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:37.906895   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.017s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.907404   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:38.077622   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.170s	user 0.133s	sys 0.037s 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":925,"lbm_read_time_us":12365,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29971,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:16:38.078097   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=10.126437
I20260812 06:16:38.124248   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.046s	user 0.041s	sys 0.000s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19722,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.124809   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:38.134711   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.135213   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:38.258780   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.123s	user 0.096s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":625,"lbm_read_time_us":8075,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25932,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:16:38.259475   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=10.126437
I20260812 06:16:38.291436   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.032s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15433,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.292575   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:38.310173   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.017s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.310624   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:38.437520   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":6905,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29477,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:38.438073   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=10.126437
I20260812 06:16:38.476210   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19285,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.476716   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:38.493733   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.494292   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:38.614768   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.120s	user 0.089s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1282,"lbm_read_time_us":7156,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26701,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:16:38.615429   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=11.118625
I20260812 06:16:38.661113   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.045s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18502,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:38.661646   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:38.685425   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":6031,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:16:38.685920   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:38.696105   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:16:38.696614   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:38.868384   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.172s	user 0.095s	sys 0.075s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":192,"lbm_read_time_us":11108,"lbm_reads_lt_1ms":573,"lbm_write_time_us":38092,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2500}
I20260812 06:16:38.869066   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:38.926606   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.057s	user 0.027s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.927198   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:38.937299   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.937958   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:38.978530   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.040s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1605,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1669,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:38.979336   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling LogGCOp(dcdc13f42b1e4798ae387713b05a86f5): free 133024383 bytes of WAL
I20260812 06:16:38.979553   375 log_reader.cc:385] T dcdc13f42b1e4798ae387713b05a86f5: removed 13 log segments from log reader
I20260812 06:16:38.979593   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000003 (ops 12-16)
I20260812 06:16:38.979620   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000004 (ops 17-21)
I20260812 06:16:38.979662   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000005 (ops 22-26)
I20260812 06:16:38.979703   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000006 (ops 27-30)
I20260812 06:16:38.979749   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000007 (ops 31-35)
I20260812 06:16:38.979787   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000008 (ops 36-40)
I20260812 06:16:38.979830   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000009 (ops 41-45)
I20260812 06:16:38.979866   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000010 (ops 46-50)
I20260812 06:16:38.979902   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000011 (ops 51-55)
I20260812 06:16:38.979944   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000012 (ops 56-60)
I20260812 06:16:38.979983   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000013 (ops 61-65)
I20260812 06:16:38.980020   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000014 (ops 66-70)
I20260812 06:16:38.980057   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000015 (ops 71-75)
I20260812 06:16:39.007284   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: LogGCOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.028s	user 0.002s	sys 0.025s Metrics: {}
I20260812 06:16:39.007747   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:39.021824   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:39.022224   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:39.031034   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3218,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.031386   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5): 492 bytes on disk
I20260812 06:16:39.031766   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.032186   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:39.279781   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.247s	user 0.183s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":198,"lbm_read_time_us":13976,"lbm_reads_lt_1ms":774,"lbm_write_time_us":46175,"lbm_writes_lt_1ms":743,"mutex_wait_us":1,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:16:39.282647   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:39.332568   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.050s	user 0.038s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19471,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.333110   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=3.181125
I20260812 06:16:39.348587   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5760,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:39.349095   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:39.358348   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3429,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.358922   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:39.538735   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.180s	user 0.146s	sys 0.031s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":625,"lbm_read_time_us":13155,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33136,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3000}
I20260812 06:16:39.539575   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=15.087375
I20260812 06:16:39.585436   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.046s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16820139,"delete_count":0,"lbm_write_time_us":19402,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:39.586737   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:39.611960   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.025s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5188,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.612402   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:39.625715   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.626418   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:39.786244   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.160s	user 0.131s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":223,"lbm_read_time_us":11353,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35559,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":3000}
I20260812 06:16:39.786722   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:39.839248   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.052s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22449,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.839799   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:39.851739   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3823,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.852226   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:40.020198   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.168s	user 0.127s	sys 0.024s 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":990,"lbm_read_time_us":10697,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32674,"lbm_writes_lt_1ms":543,"mutex_wait_us":250,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:16:40.020944   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:40.067981   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.047s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21466,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.068461   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:40.079948   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3986,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.080492   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:40.257566   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.177s	user 0.130s	sys 0.040s 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":937,"lbm_read_time_us":10510,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32231,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:16:40.258370   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:40.317368   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.059s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20311,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.317847   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:40.329236   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.329922   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:40.359619   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.029s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1277,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1436,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:40.360296   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling LogGCOp(dcdc13f42b1e4798ae387713b05a86f5): free 120553402 bytes of WAL
I20260812 06:16:40.360507   375 log_reader.cc:385] T dcdc13f42b1e4798ae387713b05a86f5: removed 12 log segments from log reader
I20260812 06:16:40.360563   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000016 (ops 76-80)
I20260812 06:16:40.360610   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000017 (ops 81-84)
I20260812 06:16:40.360663   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000018 (ops 85-89)
I20260812 06:16:40.360702   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000019 (ops 90-94)
I20260812 06:16:40.360735   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000020 (ops 95-99)
I20260812 06:16:40.360771   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000021 (ops 100-104)
I20260812 06:16:40.360806   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000022 (ops 105-109)
I20260812 06:16:40.360841   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000023 (ops 110-114)
I20260812 06:16:40.360877   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000024 (ops 115-118)
I20260812 06:16:40.360911   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000025 (ops 119-123)
I20260812 06:16:40.360948   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000026 (ops 124-128)
I20260812 06:16:40.360988   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000027 (ops 129-133)
I20260812 06:16:40.386209   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: LogGCOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:40.386670   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=3.181125
I20260812 06:16:40.404834   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6488,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:40.405318   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:40.418084   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4895,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.418597   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5): 463 bytes on disk
I20260812 06:16:40.419178   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:16:40.419698   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:40.629865   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.210s	user 0.153s	sys 0.053s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":156,"lbm_read_time_us":13722,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36844,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:16:40.630393   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=18.063937
I20260812 06:16:40.693418   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.063s	user 0.057s	sys 0.004s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":28587,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:40.693949   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:40.709569   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.710000   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:40.871672   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.162s	user 0.129s	sys 0.032s 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":712,"lbm_read_time_us":9782,"lbm_reads_lt_1ms":668,"lbm_write_time_us":35044,"lbm_writes_lt_1ms":643,"mutex_wait_us":294,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":3000}
I20260812 06:16:40.872376   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:40.929332   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.057s	user 0.039s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26463,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.929836   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:40.944959   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.945591   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:41.106092   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.160s	user 0.108s	sys 0.043s 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":829,"lbm_read_time_us":8773,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31693,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:16:41.106961   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:41.161589   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.054s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23143,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.162128   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:41.306954   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.145s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":531,"lbm_read_time_us":8174,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21682,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:16:41.307670   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:41.354790   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.047s	user 0.016s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19726,"lbm_writes_lt_1ms":403,"mutex_wait_us":1,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.355362   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:41.367089   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.367547   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:41.542235   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.175s	user 0.122s	sys 0.052s 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":281,"lbm_read_time_us":11455,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33287,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:41.542960   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:41.598443   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.055s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23925,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.599098   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:41.612017   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.612576   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:41.792263   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.180s	user 0.133s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":11717,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36080,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:16:41.792973   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=14.095187
I20260812 06:16:41.838769   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.046s	user 0.024s	sys 0.017s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":20726,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.839361   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=2.188937
I20260812 06:16:41.855684   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.856274   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:41.891328   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushMRSOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1356,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1892,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:41.892050   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling LogGCOp(dcdc13f42b1e4798ae387713b05a86f5): free 128867668 bytes of WAL
I20260812 06:16:41.892279   375 log_reader.cc:385] T dcdc13f42b1e4798ae387713b05a86f5: removed 13 log segments from log reader
I20260812 06:16:41.892323   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000028 (ops 134-138)
I20260812 06:16:41.892352   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000029 (ops 139-142)
I20260812 06:16:41.892369   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000030 (ops 143-147)
I20260812 06:16:41.892428   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000031 (ops 148-152)
I20260812 06:16:41.892472   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000032 (ops 153-156)
I20260812 06:16:41.892498   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000033 (ops 157-161)
I20260812 06:16:41.892555   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000034 (ops 162-166)
I20260812 06:16:41.892584   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000035 (ops 167-171)
I20260812 06:16:41.892637   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000036 (ops 172-176)
I20260812 06:16:41.892676   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000037 (ops 177-181)
I20260812 06:16:41.892709   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000038 (ops 182-186)
I20260812 06:16:41.892747   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000039 (ops 187-190)
I20260812 06:16:41.892809   375 log.cc:1079] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/dcdc13f42b1e4798ae387713b05a86f5/wal-000000040 (ops 191-195)
I20260812 06:16:41.919605   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: LogGCOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:41.920213   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=6.157687
I20260812 06:16:41.948654   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: FlushDeltaMemStoresOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":8164054,"delete_count":0,"lbm_write_time_us":8048,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":995}
I20260812 06:16:41.949148   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5): 492 bytes on disk
I20260812 06:16:41.949584   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: UndoDeltaBlockGCOp(dcdc13f42b1e4798ae387713b05a86f5) 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:16:41.950115   448 maintenance_manager.cc:419] P f26c972b09d34c8a8b02605a0d3f4cfa: Scheduling MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5): perf score=1.000000
I20260812 06:16:41.976503 32716 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.710s	user 1.731s	sys 0.100s
I20260812 06:16:42.081046 32716 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.104s	user 0.002s	sys 0.000s
I20260812 06:16:42.081676 32716 tablet_server.cc:179] TabletServer@127.31.243.1:0 shutting down...
I20260812 06:16:42.150159   375 maintenance_manager.cc:643] P f26c972b09d34c8a8b02605a0d3f4cfa: MajorDeltaCompactionOp(dcdc13f42b1e4798ae387713b05a86f5) complete. Timing: real 0.200s	user 0.111s	sys 0.088s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32938603,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":583,"lbm_read_time_us":15113,"lbm_reads_lt_1ms":764,"lbm_write_time_us":35214,"lbm_writes_lt_1ms":742,"mutex_wait_us":83,"peak_mem_usage":87928009,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":81,"threads_started":1,"update_count":3495}
I20260812 06:16:42.150986 32716 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:42.151604 32716 tablet_replica.cc:333] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa: stopping tablet replica
I20260812 06:16:42.151873 32716 raft_consensus.cc:2243] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:42.152140 32716 raft_consensus.cc:2272] T dcdc13f42b1e4798ae387713b05a86f5 P f26c972b09d34c8a8b02605a0d3f4cfa [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:42.168515 32716 tablet_server.cc:196] TabletServer@127.31.243.1:0 shutdown complete.
I20260812 06:16:42.209810 32716 master.cc:562] Master@127.31.243.62:35479 shutting down...
I20260812 06:16:42.213774 32716 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:42.213979 32716 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:42.214083 32716 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4f0f9a7b57734999ab086aeab95c8b2a: stopping tablet replica
I20260812 06:16:42.226599 32716 master.cc:584] Master@127.31.243.62:35479 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5317 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:42.322165 32716 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.243.62:43401
I20260812 06:16:42.322619 32716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.324798   486 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:16:42.324841   485 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:16:42.324896 32716 server_base.cc:1061] running on GCE node
W20260812 06:16:42.324977   488 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:16:42.325181 32716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.325241 32716 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:16:42.325266 32716 hybrid_clock.cc:648] HybridClock initialized: now 1786515402325266 us; error 0 us; skew 500 ppm
I20260812 06:16:42.326156 32716 webserver.cc:533] Webserver started at http://127.31.243.62:38377/ using document root <none> and password file <none>
I20260812 06:16:42.326346 32716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.326417 32716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.326496 32716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.326974 32716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/master-0-root/instance:
uuid: "880782071116424387fa986fd5acf4d6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-7c35"
I20260812 06:16:42.328480 32716 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:42.329435   494 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:16:42.329738 32716 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:42.329804 32716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/master-0-root
uuid: "880782071116424387fa986fd5acf4d6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-7c35"
I20260812 06:16:42.329861 32716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-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:16:42.350417 32716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.350831 32716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.355049 32716 rpc_server.cc:307] RPC server started. Bound to: 127.31.243.62:43401
I20260812 06:16:42.355901   560 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.243.62:43401 every 8 connection(s)
I20260812 06:16:42.360787   562 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:16:42.362731   562 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6: Bootstrap starting.
I20260812 06:16:42.363581   562 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.364647   562 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6: No bootstrap required, opened a new log
I20260812 06:16:42.365056   562 raft_consensus.cc:359] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "880782071116424387fa986fd5acf4d6" member_type: VOTER }
I20260812 06:16:42.365142   562 raft_consensus.cc:385] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.365200   562 raft_consensus.cc:740] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 880782071116424387fa986fd5acf4d6, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.365357   562 consensus_queue.cc:260] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [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: "880782071116424387fa986fd5acf4d6" member_type: VOTER }
I20260812 06:16:42.365427   562 raft_consensus.cc:399] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.365450   562 raft_consensus.cc:493] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.365535   562 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.366258   562 raft_consensus.cc:515] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "880782071116424387fa986fd5acf4d6" member_type: VOTER }
I20260812 06:16:42.366408   562 leader_election.cc:304] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [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: 880782071116424387fa986fd5acf4d6; no voters: 
I20260812 06:16:42.366621   562 leader_election.cc:290] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.366763   566 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.366997   566 raft_consensus.cc:697] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 1 LEADER]: Becoming Leader. State: Replica: 880782071116424387fa986fd5acf4d6, State: Running, Role: LEADER
I20260812 06:16:42.367084   562 sys_catalog.cc:565] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:42.367177   566 consensus_queue.cc:237] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [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: "880782071116424387fa986fd5acf4d6" member_type: VOTER }
I20260812 06:16:42.367626   567 sys_catalog.cc:455] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "880782071116424387fa986fd5acf4d6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "880782071116424387fa986fd5acf4d6" member_type: VOTER } }
I20260812 06:16:42.367740   567 sys_catalog.cc:458] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.367645   569 sys_catalog.cc:455] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 880782071116424387fa986fd5acf4d6. Latest consensus state: current_term: 1 leader_uuid: "880782071116424387fa986fd5acf4d6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "880782071116424387fa986fd5acf4d6" member_type: VOTER } }
I20260812 06:16:42.367806   569 sys_catalog.cc:458] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.368369   573 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:42.369040   573 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:42.369225 32716 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:42.370883   573 catalog_manager.cc:1383] Generated new cluster ID: 44ff497ffb2b47d38ca83e81bd356dcb
I20260812 06:16:42.370944   573 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:42.386873   573 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:42.387426   573 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:42.399915   573 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6: Generated new TSK 0
I20260812 06:16:42.400116   573 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:42.401626 32716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.403733   594 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:16:42.403824 32716 server_base.cc:1061] running on GCE node
W20260812 06:16:42.403666   595 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:16:42.403677   597 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:16:42.404112 32716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.404176 32716 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:16:42.404215 32716 hybrid_clock.cc:648] HybridClock initialized: now 1786515402404214 us; error 0 us; skew 500 ppm
I20260812 06:16:42.405021 32716 webserver.cc:533] Webserver started at http://127.31.243.1:35151/ using document root <none> and password file <none>
I20260812 06:16:42.405208 32716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.405285 32716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.405364 32716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.405773 32716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/instance:
uuid: "2834885ed5ca49dba1859b31aca231c6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-7c35"
I20260812 06:16:42.407464 32716 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:42.408387   603 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:16:42.408612 32716 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:42.408702 32716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root
uuid: "2834885ed5ca49dba1859b31aca231c6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-7c35"
I20260812 06:16:42.408795 32716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-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:16:42.441365 32716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.441851 32716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.442200 32716 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:42.442713 32716 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:42.442777 32716 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.442830 32716 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:42.442915 32716 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.447438 32716 rpc_server.cc:307] RPC server started. Bound to: 127.31.243.1:46747
I20260812 06:16:42.447520   681 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.243.1:46747 every 8 connection(s)
I20260812 06:16:42.457818   682 heartbeater.cc:344] Connected to a master server at 127.31.243.62:43401
I20260812 06:16:42.458005   682 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:42.458292   682 heartbeater.cc:507] Master 127.31.243.62:43401 requested a full tablet report, sending...
I20260812 06:16:42.459218   518 ts_manager.cc:194] Registered new tserver with Master: 2834885ed5ca49dba1859b31aca231c6 (127.31.243.1:46747)
I20260812 06:16:42.460134 32716 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012208576s
I20260812 06:16:42.460151   518 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40872
I20260812 06:16:42.467694   518 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40888:
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:16:42.476939   637 tablet_service.cc:1511] Processing CreateTablet for tablet 03721fea5d3d44c3807d4a42429dd374 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c782a6cf33544314bec5f20f5cf8fe9e]), partition=
I20260812 06:16:42.477250   637 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 03721fea5d3d44c3807d4a42429dd374. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:42.479996   698 tablet_bootstrap.cc:492] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Bootstrap starting.
I20260812 06:16:42.480888   698 tablet_bootstrap.cc:654] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.481962   698 tablet_bootstrap.cc:492] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: No bootstrap required, opened a new log
I20260812 06:16:42.482038   698 ts_tablet_manager.cc:1403] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:42.482427   698 raft_consensus.cc:359] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2834885ed5ca49dba1859b31aca231c6" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 46747 } }
I20260812 06:16:42.482558   698 raft_consensus.cc:385] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.482594   698 raft_consensus.cc:740] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2834885ed5ca49dba1859b31aca231c6, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.482734   698 consensus_queue.cc:260] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [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: "2834885ed5ca49dba1859b31aca231c6" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 46747 } }
I20260812 06:16:42.482846   698 raft_consensus.cc:399] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.482913   698 raft_consensus.cc:493] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.482965   698 raft_consensus.cc:3060] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.483821   698 raft_consensus.cc:515] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2834885ed5ca49dba1859b31aca231c6" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 46747 } }
I20260812 06:16:42.483945   698 leader_election.cc:304] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [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: 2834885ed5ca49dba1859b31aca231c6; no voters: 
I20260812 06:16:42.484108   698 leader_election.cc:290] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.484261   700 raft_consensus.cc:2804] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.484427   682 heartbeater.cc:499] Master 127.31.243.62:43401 was elected leader, sending a full tablet report...
I20260812 06:16:42.484467   700 raft_consensus.cc:697] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 1 LEADER]: Becoming Leader. State: Replica: 2834885ed5ca49dba1859b31aca231c6, State: Running, Role: LEADER
I20260812 06:16:42.484422   698 ts_tablet_manager.cc:1434] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:42.484688   700 consensus_queue.cc:237] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [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: "2834885ed5ca49dba1859b31aca231c6" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 46747 } }
I20260812 06:16:42.486202   518 catalog_manager.cc:5719] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2834885ed5ca49dba1859b31aca231c6 (127.31.243.1). New cstate: current_term: 1 leader_uuid: "2834885ed5ca49dba1859b31aca231c6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2834885ed5ca49dba1859b31aca231c6" member_type: VOTER last_known_addr { host: "127.31.243.1" port: 46747 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:42.545773 32716 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.011s	sys 0.012s
I20260812 06:16:42.698498   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushMRSOp(03721fea5d3d44c3807d4a42429dd374): perf score=19.054940
I20260812 06:16:42.859408   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushMRSOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.161s	user 0.109s	sys 0.051s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":310,"dirs.run_wall_time_us":1007,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39956,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:42.860384   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling LogGCOp(03721fea5d3d44c3807d4a42429dd374): free 20743880 bytes of WAL
I20260812 06:16:42.860661   608 log_reader.cc:385] T 03721fea5d3d44c3807d4a42429dd374: removed 2 log segments from log reader
I20260812 06:16:42.860702   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000001 (ops 1-6)
I20260812 06:16:42.860731   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000002 (ops 7-11)
I20260812 06:16:42.864955   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: LogGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:42.865331   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374): 16411396 bytes on disk
I20260812 06:16:42.865796   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.866204   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:42.884693   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.018s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.885131   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:43.039515   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.154s	user 0.100s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":387,"lbm_read_time_us":10018,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24761,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":323,"threads_started":5,"update_count":2000}
I20260812 06:16:43.040056   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=11.118625
I20260812 06:16:43.077795   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.038s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15838,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:43.078320   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:43.098647   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.020s	user 0.013s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5172,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.100311   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:43.263789   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.163s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":381,"lbm_read_time_us":10527,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27218,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.264735   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:43.316124   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.051s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21518,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.316605   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:43.327127   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.327566   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:43.486334   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.159s	user 0.119s	sys 0.037s 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":458,"lbm_read_time_us":11764,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29538,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2500}
I20260812 06:16:43.487052   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=11.118625
I20260812 06:16:43.521835   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.035s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14320,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:43.522293   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:43.536252   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5304,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.536710   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:43.681598   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.145s	user 0.093s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":9563,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28509,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:16:43.682386   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=11.118625
I20260812 06:16:43.730279   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.048s	user 0.037s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16642,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:43.730880   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:43.744807   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.014s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3500,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.745285   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:43.905689   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.160s	user 0.106s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":880,"lbm_read_time_us":9025,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25115,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:43.906371   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:43.952450   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.046s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19853,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.953039   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:43.963519   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.964175   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:44.119108   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.155s	user 0.081s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":9126,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27505,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:16:44.120025   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=10.126437
I20260812 06:16:44.155542   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.035s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15017,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.156088   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:44.172376   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.173203   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushMRSOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:44.198433   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushMRSOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.025s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1454,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1397,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:44.199059   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling LogGCOp(03721fea5d3d44c3807d4a42429dd374): free 120553376 bytes of WAL
I20260812 06:16:44.199266   608 log_reader.cc:385] T 03721fea5d3d44c3807d4a42429dd374: removed 12 log segments from log reader
I20260812 06:16:44.199324   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000003 (ops 12-16)
I20260812 06:16:44.199376   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000004 (ops 17-21)
I20260812 06:16:44.199441   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000005 (ops 22-26)
I20260812 06:16:44.199491   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000006 (ops 27-31)
I20260812 06:16:44.199533   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000007 (ops 32-36)
I20260812 06:16:44.199568   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000008 (ops 37-40)
I20260812 06:16:44.199604   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000009 (ops 41-45)
I20260812 06:16:44.199664   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000010 (ops 46-50)
I20260812 06:16:44.199700   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000011 (ops 51-54)
I20260812 06:16:44.199738   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000012 (ops 55-59)
I20260812 06:16:44.199772   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000013 (ops 60-64)
I20260812 06:16:44.199808   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000014 (ops 65-69)
I20260812 06:16:44.225492   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: LogGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:44.225901   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=4.173312
I20260812 06:16:44.239935   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":5333392,"delete_count":0,"lbm_write_time_us":5491,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:16:44.240377   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.196750
I20260812 06:16:44.249262   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.009s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":2788,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:16:44.249761   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling LogGCOp(03721fea5d3d44c3807d4a42429dd374): free 12017932 bytes of WAL
I20260812 06:16:44.250001   608 log_reader.cc:385] T 03721fea5d3d44c3807d4a42429dd374: removed 1 log segments from log reader
I20260812 06:16:44.250066   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000015 (ops 70-74)
I20260812 06:16:44.252823   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: LogGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:44.253142   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374): 481 bytes on disk
I20260812 06:16:44.253541   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.253965   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:44.458176   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.204s	user 0.142s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":78,"lbm_read_time_us":10544,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34288,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:16:44.459105   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=15.087375
I20260812 06:16:44.503794   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.044s	user 0.019s	sys 0.025s Metrics: {"bytes_written":16697073,"delete_count":0,"lbm_write_time_us":18862,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2035}
I20260812 06:16:44.504388   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:44.519151   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5184,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:16:44.519670   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:44.691731   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.172s	user 0.116s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":650,"lbm_read_time_us":11046,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26579,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":2500}
I20260812 06:16:44.692440   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:44.735186   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.043s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17736,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.735658   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:44.768518   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.033s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4189,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.769127   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:44.784945   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.785516   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:44.996304   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.211s	user 0.139s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":902,"lbm_read_time_us":15809,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32184,"lbm_writes_lt_1ms":643,"mutex_wait_us":323,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":39936,"update_count":3000}
I20260812 06:16:44.997117   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:45.054359   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.057s	user 0.030s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22808,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.055197   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=3.181125
I20260812 06:16:45.079339   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.024s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":5293,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:16:45.079773   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:45.089525   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":3723,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:16:45.089949   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:45.300626   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.211s	user 0.143s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":610,"lbm_read_time_us":13274,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34224,"lbm_writes_lt_1ms":643,"mutex_wait_us":282,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:45.301321   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=15.087375
I20260812 06:16:45.345436   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":17230388,"delete_count":0,"lbm_write_time_us":18887,"lbm_writes_lt_1ms":423,"reinsert_count":0,"update_count":2100}
I20260812 06:16:45.345901   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:45.367551   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.021s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:16:45.368086   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:45.380043   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.380944   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:45.583580   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.202s	user 0.132s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1293,"lbm_read_time_us":13391,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35048,"lbm_writes_lt_1ms":643,"mutex_wait_us":416,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":3000}
I20260812 06:16:45.584286   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:45.643937   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.059s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22583,"lbm_writes_lt_1ms":403,"mutex_wait_us":2,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.644479   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:45.655392   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.655876   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushMRSOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:45.687465   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushMRSOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1425,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1851,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:45.688091   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling LogGCOp(03721fea5d3d44c3807d4a42429dd374): free 108535428 bytes of WAL
I20260812 06:16:45.688313   608 log_reader.cc:385] T 03721fea5d3d44c3807d4a42429dd374: removed 11 log segments from log reader
I20260812 06:16:45.688354   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000016 (ops 75-79)
I20260812 06:16:45.688383   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000017 (ops 80-84)
I20260812 06:16:45.688439   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000018 (ops 85-88)
I20260812 06:16:45.688496   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000019 (ops 89-93)
I20260812 06:16:45.688539   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000020 (ops 94-98)
I20260812 06:16:45.688578   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000021 (ops 99-103)
I20260812 06:16:45.688618   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000022 (ops 104-108)
I20260812 06:16:45.688657   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000023 (ops 109-112)
I20260812 06:16:45.688697   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000024 (ops 113-117)
I20260812 06:16:45.688736   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000025 (ops 118-122)
I20260812 06:16:45.688776   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000026 (ops 123-127)
I20260812 06:16:45.711512   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: LogGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:45.711985   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374): 463 bytes on disk
I20260812 06:16:45.712476   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.713014   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=3.181125
I20260812 06:16:45.738138   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.025s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6272,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:45.738605   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling LogGCOp(03721fea5d3d44c3807d4a42429dd374): free 12018000 bytes of WAL
I20260812 06:16:45.738817   608 log_reader.cc:385] T 03721fea5d3d44c3807d4a42429dd374: removed 1 log segments from log reader
I20260812 06:16:45.738915   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000027 (ops 128-132)
I20260812 06:16:45.741217   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: LogGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:45.741590   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:45.751748   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3479,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.752449   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:46.001279   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.249s	user 0.150s	sys 0.091s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":785,"lbm_read_time_us":16730,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45313,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":36480,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:16:46.002003   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=18.063937
I20260812 06:16:46.063092   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.060s	user 0.044s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27059,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:46.063552   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:46.075650   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.076076   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:46.239078   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.163s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":12287,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33335,"lbm_writes_lt_1ms":643,"mutex_wait_us":106,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":3000}
I20260812 06:16:46.239617   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:46.290558   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.051s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21221,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.291131   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:46.308306   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.017s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.308799   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:46.459764   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.151s	user 0.111s	sys 0.039s 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":906,"lbm_read_time_us":9843,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28463,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:16:46.460546   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:46.512061   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.051s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22158,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.512678   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:46.669626   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.157s	user 0.098s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":843,"lbm_read_time_us":10450,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24040,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:16:46.670418   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:46.722309   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.052s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21973,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.722942   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:46.735667   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.736443   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:46.928858   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.192s	user 0.115s	sys 0.072s 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":241,"lbm_read_time_us":11413,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32370,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:16:46.929593   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=14.095187
I20260812 06:16:46.982301   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.053s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19749,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.982944   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:46.995401   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.996096   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:47.219511   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.223s	user 0.182s	sys 0.035s 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":224,"lbm_read_time_us":11718,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36711,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:16:47.220335   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=18.063937
I20260812 06:16:47.284379   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.064s	user 0.035s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":25547,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:47.284960   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:47.295486   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.295980   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushMRSOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:47.352660   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushMRSOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.056s	user 0.031s	sys 0.022s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1519,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2290,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:16:47.353587   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling LogGCOp(03721fea5d3d44c3807d4a42429dd374): free 128867720 bytes of WAL
I20260812 06:16:47.353861   608 log_reader.cc:385] T 03721fea5d3d44c3807d4a42429dd374: removed 13 log segments from log reader
I20260812 06:16:47.353920   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000028 (ops 133-137)
I20260812 06:16:47.353960   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000029 (ops 138-142)
I20260812 06:16:47.354040   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000030 (ops 143-146)
I20260812 06:16:47.354082   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000031 (ops 147-151)
I20260812 06:16:47.354148   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000032 (ops 152-156)
I20260812 06:16:47.354182   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000033 (ops 157-160)
I20260812 06:16:47.354246   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000034 (ops 161-165)
I20260812 06:16:47.354285   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000035 (ops 166-170)
I20260812 06:16:47.354342   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000036 (ops 171-174)
I20260812 06:16:47.354375   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000037 (ops 175-179)
I20260812 06:16:47.354435   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000038 (ops 180-184)
I20260812 06:16:47.354471   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000039 (ops 185-189)
I20260812 06:16:47.354535   608 log.cc:1079] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: Deleting log segment in path: /tmp/dist-test-taskXmyjCH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396982481-32716-0/minicluster-data/ts-0-root/wals/03721fea5d3d44c3807d4a42429dd374/wal-000000040 (ops 190-194)
I20260812 06:16:47.388314   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: LogGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:16:47.388906   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374): 507 bytes on disk
I20260812 06:16:47.389434   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: UndoDeltaBlockGCOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.390494   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=2.188937
I20260812 06:16:47.406942   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.016s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.407666   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374): perf score=1.000000
I20260812 06:16:47.541026 32716 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.995s	user 1.836s	sys 0.192s
I20260812 06:16:47.661593   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: MajorDeltaCompactionOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.254s	user 0.173s	sys 0.080s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979635,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1978,"lbm_read_time_us":15152,"lbm_reads_lt_1ms":765,"lbm_write_time_us":46240,"lbm_writes_lt_1ms":743,"mutex_wait_us":401,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":34560,"thread_start_us":130,"threads_started":1,"update_count":3500}
I20260812 06:16:47.662231   683 maintenance_manager.cc:419] P 2834885ed5ca49dba1859b31aca231c6: Scheduling FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374): perf score=6.157687
I20260812 06:16:47.664584 32716 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.123s	user 0.004s	sys 0.000s
I20260812 06:16:47.665324 32716 tablet_server.cc:179] TabletServer@127.31.243.1:0 shutting down...
I20260812 06:16:47.687582   608 maintenance_manager.cc:643] P 2834885ed5ca49dba1859b31aca231c6: FlushDeltaMemStoresOp(03721fea5d3d44c3807d4a42429dd374) complete. Timing: real 0.025s	user 0.009s	sys 0.016s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":11003,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.688212 32716 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:47.688433 32716 tablet_replica.cc:333] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6: stopping tablet replica
I20260812 06:16:47.688556 32716 raft_consensus.cc:2243] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.688710 32716 raft_consensus.cc:2272] T 03721fea5d3d44c3807d4a42429dd374 P 2834885ed5ca49dba1859b31aca231c6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.692171 32716 tablet_server.cc:196] TabletServer@127.31.243.1:0 shutdown complete.
I20260812 06:16:47.719535 32716 master.cc:562] Master@127.31.243.62:43401 shutting down...
I20260812 06:16:47.723153 32716 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.723338 32716 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.723389 32716 tablet_replica.cc:333] T 00000000000000000000000000000000 P 880782071116424387fa986fd5acf4d6: stopping tablet replica
I20260812 06:16:47.736840 32716 master.cc:584] Master@127.31.243.62:43401 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5508 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10827 ms total)

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