[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:07.516922 16239 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.219.254:40891
I20260812 06:18:07.517997 16239 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:07.518700 16239 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:07.525040 16244 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:07.525126 16247 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:07.525040 16245 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:07.525720 16239 server_base.cc:1061] running on GCE node
I20260812 06:18:07.526217 16239 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:07.526345 16239 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:07.526410 16239 hybrid_clock.cc:648] HybridClock initialized: now 1786515487526407 us; error 0 us; skew 500 ppm
I20260812 06:18:07.528275 16239 webserver.cc:533] Webserver started at http://127.15.219.254:42197/ using document root <none> and password file <none>
I20260812 06:18:07.528847 16239 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:07.528937 16239 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:07.529177 16239 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:07.530957 16239 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/master-0-root/instance:
uuid: "8bd7fd22282a4401b648a42089b56deb"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-bt4h"
I20260812 06:18:07.534490 16239 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:07.536664 16254 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.537731 16239 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:07.537884 16239 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/master-0-root
uuid: "8bd7fd22282a4401b648a42089b56deb"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-bt4h"
I20260812 06:18:07.537999 16239 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:07.547780 16239 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:07.548441 16239 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:07.548626 16239 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:07.556217 16239 rpc_server.cc:307] RPC server started. Bound to: 127.15.219.254:40891
I20260812 06:18:07.556226 16316 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.219.254:40891 every 8 connection(s)
I20260812 06:18:07.558475 16317 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:07.564131 16317 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb: Bootstrap starting.
I20260812 06:18:07.566583 16317 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:07.567546 16317 log.cc:826] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:07.569320 16317 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb: No bootstrap required, opened a new log
I20260812 06:18:07.572280 16317 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bd7fd22282a4401b648a42089b56deb" member_type: VOTER }
I20260812 06:18:07.572446 16317 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:07.572535 16317 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8bd7fd22282a4401b648a42089b56deb, State: Initialized, Role: FOLLOWER
I20260812 06:18:07.573227 16317 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [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: "8bd7fd22282a4401b648a42089b56deb" member_type: VOTER }
I20260812 06:18:07.573398 16317 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:07.573477 16317 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:07.573648 16317 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:07.574457 16317 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bd7fd22282a4401b648a42089b56deb" member_type: VOTER }
I20260812 06:18:07.574921 16317 leader_election.cc:304] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [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: 8bd7fd22282a4401b648a42089b56deb; no voters: 
I20260812 06:18:07.575249 16317 leader_election.cc:290] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:07.575424 16321 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:07.575688 16321 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 1 LEADER]: Becoming Leader. State: Replica: 8bd7fd22282a4401b648a42089b56deb, State: Running, Role: LEADER
I20260812 06:18:07.576133 16321 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [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: "8bd7fd22282a4401b648a42089b56deb" member_type: VOTER }
I20260812 06:18:07.576293 16317 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:07.578172 16322 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8bd7fd22282a4401b648a42089b56deb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bd7fd22282a4401b648a42089b56deb" member_type: VOTER } }
I20260812 06:18:07.578164 16323 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8bd7fd22282a4401b648a42089b56deb. Latest consensus state: current_term: 1 leader_uuid: "8bd7fd22282a4401b648a42089b56deb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bd7fd22282a4401b648a42089b56deb" member_type: VOTER } }
I20260812 06:18:07.578299 16323 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:07.578299 16322 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:07.578742 16334 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:07.578877 16239 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:07.581038 16334 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:07.585637 16334 catalog_manager.cc:1383] Generated new cluster ID: c03d6bc4591343b7b9511e7641eb882d
I20260812 06:18:07.585716 16334 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:07.644797 16334 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:07.645952 16334 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:07.653849 16334 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb: Generated new TSK 0
I20260812 06:18:07.654661 16334 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:07.707944 16239 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:07.710726 16343 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:07.710865 16346 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:07.711135 16239 server_base.cc:1061] running on GCE node
W20260812 06:18:07.711164 16344 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:07.711443 16239 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:07.711506 16239 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:07.711541 16239 hybrid_clock.cc:648] HybridClock initialized: now 1786515487711540 us; error 0 us; skew 500 ppm
I20260812 06:18:07.712507 16239 webserver.cc:533] Webserver started at http://127.15.219.193:46357/ using document root <none> and password file <none>
I20260812 06:18:07.712690 16239 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:07.712761 16239 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:07.712862 16239 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:07.713279 16239 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/instance:
uuid: "054d4512c71246a0982467f969074940"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-bt4h"
I20260812 06:18:07.714850 16239 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:07.715864 16351 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.716117 16239 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:07.716190 16239 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root
uuid: "054d4512c71246a0982467f969074940"
format_stamp: "Formatted at 2026-08-12 06:18:07 on dist-test-slave-bt4h"
I20260812 06:18:07.716276 16239 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:07.735351 16239 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:07.735839 16239 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:07.736356 16239 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:07.737298 16239 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:07.737360 16239 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.737429 16239 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:07.737475 16239 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:07.743736 16239 rpc_server.cc:307] RPC server started. Bound to: 127.15.219.193:41435
I20260812 06:18:07.743848 16418 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.219.193:41435 every 8 connection(s)
I20260812 06:18:07.753901 16420 heartbeater.cc:344] Connected to a master server at 127.15.219.254:40891
I20260812 06:18:07.754165 16420 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:07.754685 16420 heartbeater.cc:507] Master 127.15.219.254:40891 requested a full tablet report, sending...
I20260812 06:18:07.756134 16273 ts_manager.cc:194] Registered new tserver with Master: 054d4512c71246a0982467f969074940 (127.15.219.193:41435)
I20260812 06:18:07.756875 16239 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012393908s
I20260812 06:18:07.757414 16273 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45896
I20260812 06:18:07.766928 16273 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45910:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:07.781189 16379 tablet_service.cc:1511] Processing CreateTablet for tablet 244ba51da7054e048e669ebadfdda4af (DEFAULT_TABLE table=heavy-update-compaction-test [id=80d25f698683443cb894218838ef2bd7]), partition=
I20260812 06:18:07.781785 16379 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 244ba51da7054e048e669ebadfdda4af. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:07.784192 16432 tablet_bootstrap.cc:492] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Bootstrap starting.
I20260812 06:18:07.785274 16432 tablet_bootstrap.cc:654] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:07.786345 16432 tablet_bootstrap.cc:492] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: No bootstrap required, opened a new log
I20260812 06:18:07.786466 16432 ts_tablet_manager.cc:1403] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:07.786948 16432 raft_consensus.cc:359] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "054d4512c71246a0982467f969074940" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 41435 } }
I20260812 06:18:07.787072 16432 raft_consensus.cc:385] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:07.787120 16432 raft_consensus.cc:740] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 054d4512c71246a0982467f969074940, State: Initialized, Role: FOLLOWER
I20260812 06:18:07.787276 16432 consensus_queue.cc:260] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [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: "054d4512c71246a0982467f969074940" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 41435 } }
I20260812 06:18:07.787374 16432 raft_consensus.cc:399] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:07.787423 16432 raft_consensus.cc:493] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:07.787478 16432 raft_consensus.cc:3060] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:07.788208 16432 raft_consensus.cc:515] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "054d4512c71246a0982467f969074940" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 41435 } }
I20260812 06:18:07.788367 16432 leader_election.cc:304] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [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: 054d4512c71246a0982467f969074940; no voters: 
I20260812 06:18:07.788592 16432 leader_election.cc:290] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:07.788709 16434 raft_consensus.cc:2804] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:07.788928 16434 raft_consensus.cc:697] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 1 LEADER]: Becoming Leader. State: Replica: 054d4512c71246a0982467f969074940, State: Running, Role: LEADER
I20260812 06:18:07.789005 16432 ts_tablet_manager.cc:1434] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:07.789127 16434 consensus_queue.cc:237] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [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: "054d4512c71246a0982467f969074940" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 41435 } }
I20260812 06:18:07.789602 16420 heartbeater.cc:499] Master 127.15.219.254:40891 was elected leader, sending a full tablet report...
I20260812 06:18:07.792085 16273 catalog_manager.cc:5719] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 reported cstate change: term changed from 0 to 1, leader changed from <none> to 054d4512c71246a0982467f969074940 (127.15.219.193). New cstate: current_term: 1 leader_uuid: "054d4512c71246a0982467f969074940" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "054d4512c71246a0982467f969074940" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 41435 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:07.859483 16239 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.015s	sys 0.012s
I20260812 06:18:07.995143 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushMRSOp(244ba51da7054e048e669ebadfdda4af): perf score=15.086190
I20260812 06:18:08.166759 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushMRSOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.171s	user 0.124s	sys 0.039s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":231,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":720,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42816,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":108,"threads_started":1,"update_count":1450}
I20260812 06:18:08.168148 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling LogGCOp(244ba51da7054e048e669ebadfdda4af): free 20743880 bytes of WAL
I20260812 06:18:08.168488 16356 log_reader.cc:385] T 244ba51da7054e048e669ebadfdda4af: removed 2 log segments from log reader
I20260812 06:18:08.168561 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000001 (ops 1-6)
I20260812 06:18:08.168628 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000002 (ops 7-11)
I20260812 06:18:08.175189 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: LogGCOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:18:08.175595 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:08.193347 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.018s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.193836 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af): 12719216 bytes on disk
I20260812 06:18:08.194387 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af) 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:18:08.194880 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:08.327848 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.133s	user 0.113s	sys 0.019s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":632,"lbm_read_time_us":9252,"lbm_reads_lt_1ms":454,"lbm_write_time_us":26893,"lbm_writes_lt_1ms":433,"mutex_wait_us":50,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":290,"threads_started":5,"update_count":1950}
I20260812 06:18:08.328495 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:08.372346 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.044s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20167,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:18:08.372864 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:08.385383 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.385882 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:08.514748 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.129s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":470,"lbm_read_time_us":10953,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25828,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:08.515413 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:08.557917 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.042s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19041,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.558455 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:08.570094 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.570726 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:08.712620 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.142s	user 0.113s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":282,"lbm_read_time_us":11979,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27469,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":75648,"update_count":2000}
I20260812 06:18:08.713363 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:08.773680 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.060s	user 0.016s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17445,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:18:08.774360 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:08.785888 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4435,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.786371 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:08.955969 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.169s	user 0.112s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":629,"lbm_read_time_us":12575,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27806,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:18:08.956555 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:09.003212 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.046s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15879,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.003727 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:09.015443 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.015910 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:09.150403 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.134s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":656,"lbm_read_time_us":11137,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26608,"lbm_writes_lt_1ms":443,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:18:09.151005 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:09.200110 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.049s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16653,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.200572 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:09.211910 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.212574 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:09.334910 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.122s	user 0.097s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":10401,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23103,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":2000}
I20260812 06:18:09.335563 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:09.386046 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.050s	user 0.015s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15658,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.386741 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:09.397578 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.398089 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:09.551807 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.154s	user 0.103s	sys 0.050s 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":560,"lbm_read_time_us":11754,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26485,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:09.554639 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:09.597638 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.043s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15056,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.598116 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:09.609205 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.609957 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushMRSOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:09.651615 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushMRSOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.041s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":34,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1600,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1651,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1792}
I20260812 06:18:09.652475 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling LogGCOp(244ba51da7054e048e669ebadfdda4af): free 124257246 bytes of WAL
I20260812 06:18:09.652724 16356 log_reader.cc:385] T 244ba51da7054e048e669ebadfdda4af: removed 12 log segments from log reader
I20260812 06:18:09.652788 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000003 (ops 12-16)
I20260812 06:18:09.652848 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000004 (ops 17-21)
I20260812 06:18:09.652911 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000005 (ops 22-26)
I20260812 06:18:09.652958 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000006 (ops 27-31)
I20260812 06:18:09.653000 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000007 (ops 32-36)
I20260812 06:18:09.653041 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000008 (ops 37-41)
I20260812 06:18:09.653081 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000009 (ops 42-46)
I20260812 06:18:09.653141 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000010 (ops 47-50)
I20260812 06:18:09.653192 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000011 (ops 51-55)
I20260812 06:18:09.653234 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000012 (ops 56-60)
I20260812 06:18:09.653273 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000013 (ops 61-65)
I20260812 06:18:09.653314 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000014 (ops 66-70)
I20260812 06:18:09.685521 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: LogGCOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:09.686237 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af): 483 bytes on disk
I20260812 06:18:09.686858 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.687469 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=4.173312
I20260812 06:18:09.713929 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.026s	user 0.007s	sys 0.016s Metrics: {"bytes_written":6194893,"delete_count":0,"lbm_write_time_us":7420,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:18:09.714607 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:09.724460 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":2767,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:18:09.725107 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:09.936004 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.211s	user 0.122s	sys 0.087s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877286,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":517,"lbm_read_time_us":14220,"lbm_reads_lt_1ms":670,"lbm_write_time_us":38189,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:09.936944 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=14.095187
I20260812 06:18:10.005141 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.067s	user 0.033s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25261,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.005793 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:10.018105 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.018631 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:10.214504 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.196s	user 0.115s	sys 0.074s 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":668,"lbm_read_time_us":14695,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32379,"lbm_writes_lt_1ms":543,"mutex_wait_us":328,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:18:10.215091 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=11.118625
I20260812 06:18:10.263816 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.049s	user 0.016s	sys 0.030s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19608,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:10.264447 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:10.282665 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.283139 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:10.304174 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.021s	user 0.005s	sys 0.014s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3935,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.304767 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:10.489997 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.185s	user 0.142s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":324,"lbm_read_time_us":15013,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30518,"lbm_writes_lt_1ms":543,"mutex_wait_us":92,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:18:10.490664 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=11.118625
I20260812 06:18:10.522854 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.032s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14519,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:10.523623 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:10.541676 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.018s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5337,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.542323 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:10.669656 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.127s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":7773,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27080,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:10.670346 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:10.719300 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.049s	user 0.033s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21235,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.719873 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:10.743944 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.024s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.744539 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:10.868291 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.124s	user 0.104s	sys 0.020s 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":235,"lbm_read_time_us":8539,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23131,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32256,"update_count":2000}
I20260812 06:18:10.869037 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:10.908205 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.039s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14804,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.908843 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:10.922708 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.923199 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:11.054037 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.131s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":477,"lbm_read_time_us":8604,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26495,"lbm_writes_lt_1ms":443,"mutex_wait_us":88,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:18:11.054775 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:11.107239 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.052s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17828,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.107869 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:11.119098 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.119575 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushMRSOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:11.166252 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushMRSOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.046s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1615,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:11.167073 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling LogGCOp(244ba51da7054e048e669ebadfdda4af): free 121006444 bytes of WAL
I20260812 06:18:11.167320 16356 log_reader.cc:385] T 244ba51da7054e048e669ebadfdda4af: removed 12 log segments from log reader
I20260812 06:18:11.167364 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000015 (ops 71-75)
I20260812 06:18:11.167395 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000016 (ops 76-80)
I20260812 06:18:11.167460 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000017 (ops 81-85)
I20260812 06:18:11.167492 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000018 (ops 86-90)
I20260812 06:18:11.167533 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000019 (ops 91-95)
I20260812 06:18:11.167585 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000020 (ops 96-100)
I20260812 06:18:11.167620 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000021 (ops 101-105)
I20260812 06:18:11.167657 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000022 (ops 106-110)
I20260812 06:18:11.167696 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000023 (ops 111-114)
I20260812 06:18:11.167740 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000024 (ops 115-119)
I20260812 06:18:11.167780 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000025 (ops 120-124)
I20260812 06:18:11.167819 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000026 (ops 125-129)
I20260812 06:18:11.196095 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: LogGCOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:11.196676 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=3.181125
I20260812 06:18:11.219429 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.023s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7313,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:11.219933 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:11.230266 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.230811 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af): 447 bytes on disk
I20260812 06:18:11.231345 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:11.232477 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:11.453505 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.221s	user 0.146s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":776,"lbm_read_time_us":15582,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37632,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15616,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:18:11.454311 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=14.095187
I20260812 06:18:11.512939 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.058s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25560,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.513499 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:11.676574 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.163s	user 0.099s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":310,"lbm_read_time_us":10256,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28049,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:18:11.677352 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=14.095187
I20260812 06:18:11.731225 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.054s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22249,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.731760 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:11.744038 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.744536 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:11.936183 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.191s	user 0.114s	sys 0.067s 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":319,"lbm_read_time_us":12217,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30400,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:11.936909 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=11.118625
I20260812 06:18:11.966689 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.030s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13063,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:11.967372 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:11.986909 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6049,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.987398 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:12.117748 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.130s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1400,"lbm_read_time_us":7423,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24577,"lbm_writes_lt_1ms":443,"mutex_wait_us":747,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:12.118556 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=11.118625
I20260812 06:18:12.168110 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.049s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19161,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:12.168783 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:12.185971 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.186448 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:12.196060 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3548,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.196534 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:12.342275 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.146s	user 0.112s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":4595,"lbm_read_time_us":11910,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27063,"lbm_writes_lt_1ms":543,"mutex_wait_us":1622,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:18:12.342931 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=10.126437
I20260812 06:18:12.382977 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.040s	user 0.013s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17295,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.383560 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:12.401302 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6472,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.401750 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:12.533000 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.131s	user 0.091s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":951,"lbm_read_time_us":7667,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26118,"lbm_writes_lt_1ms":443,"mutex_wait_us":401,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:12.533830 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=11.118625
I20260812 06:18:12.583964 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.050s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17338,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:12.584501 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:12.611459 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.027s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.611954 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:12.622314 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.622795 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushMRSOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:12.664638 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushMRSOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.042s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":135,"dirs.run_wall_time_us":1271,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2037,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:12.665354 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling LogGCOp(244ba51da7054e048e669ebadfdda4af): free 112239502 bytes of WAL
I20260812 06:18:12.665587 16356 log_reader.cc:385] T 244ba51da7054e048e669ebadfdda4af: removed 11 log segments from log reader
I20260812 06:18:12.665632 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000027 (ops 130-134)
I20260812 06:18:12.665661 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000028 (ops 135-139)
I20260812 06:18:12.665727 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000029 (ops 140-144)
I20260812 06:18:12.665773 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000030 (ops 145-148)
I20260812 06:18:12.665818 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000031 (ops 149-153)
I20260812 06:18:12.665859 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000032 (ops 154-158)
I20260812 06:18:12.665900 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000033 (ops 159-163)
I20260812 06:18:12.665942 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000034 (ops 164-168)
I20260812 06:18:12.665979 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000035 (ops 169-173)
I20260812 06:18:12.666019 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000036 (ops 174-178)
I20260812 06:18:12.666059 16356 log.cc:1079] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/244ba51da7054e048e669ebadfdda4af/wal-000000037 (ops 179-183)
I20260812 06:18:12.691515 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: LogGCOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:12.691941 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=3.181125
I20260812 06:18:12.706830 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.015s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4721,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:12.707258 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af): 463 bytes on disk
I20260812 06:18:12.707640 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: UndoDeltaBlockGCOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.708146 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:12.718178 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.718955 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:12.943885 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.225s	user 0.148s	sys 0.074s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":3541,"lbm_read_time_us":17074,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40286,"lbm_writes_lt_1ms":743,"mutex_wait_us":1750,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:18:12.944723 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=15.087375
I20260812 06:18:13.003307 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.058s	user 0.045s	sys 0.012s Metrics: {"bytes_written":16820139,"delete_count":0,"lbm_write_time_us":25758,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:13.003832 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:13.025192 16239 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.166s	user 1.815s	sys 0.155s
I20260812 06:18:13.026767 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.023s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6341,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.027276 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af): perf score=2.188937
I20260812 06:18:13.037364 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: FlushDeltaMemStoresOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":500}
I20260812 06:18:13.037999 16421 maintenance_manager.cc:419] P 054d4512c71246a0982467f969074940: Scheduling MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af): perf score=1.000000
I20260812 06:18:13.083940 16239 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.058s	user 0.004s	sys 0.000s
I20260812 06:18:13.084740 16239 tablet_server.cc:179] TabletServer@127.15.219.193:0 shutting down...
I20260812 06:18:13.183765 16356 maintenance_manager.cc:643] P 054d4512c71246a0982467f969074940: MajorDeltaCompactionOp(244ba51da7054e048e669ebadfdda4af) complete. Timing: real 0.146s	user 0.114s	sys 0.031s Metrics: {"cfile_cache_hit":306,"cfile_cache_hit_bytes":12474126,"cfile_cache_miss":327,"cfile_cache_miss_bytes":16403077,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":976,"lbm_read_time_us":6988,"lbm_reads_lt_1ms":359,"lbm_write_time_us":31159,"lbm_writes_lt_1ms":643,"mutex_wait_us":381,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":3000}
I20260812 06:18:13.184470 16239 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:13.184882 16239 tablet_replica.cc:333] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940: stopping tablet replica
I20260812 06:18:13.185137 16239 raft_consensus.cc:2243] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.185403 16239 raft_consensus.cc:2272] T 244ba51da7054e048e669ebadfdda4af P 054d4512c71246a0982467f969074940 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.201879 16239 tablet_server.cc:196] TabletServer@127.15.219.193:0 shutdown complete.
I20260812 06:18:13.238806 16239 master.cc:562] Master@127.15.219.254:40891 shutting down...
I20260812 06:18:13.243340 16239 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.243556 16239 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.243649 16239 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8bd7fd22282a4401b648a42089b56deb: stopping tablet replica
I20260812 06:18:13.256048 16239 master.cc:584] Master@127.15.219.254:40891 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5836 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:13.352900 16239 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.219.254:42377
I20260812 06:18:13.353458 16239 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:13.356473 16452 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:13.356550 16455 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:13.356595 16239 server_base.cc:1061] running on GCE node
W20260812 06:18:13.356560 16453 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:13.357033 16239 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:13.357085 16239 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:13.357102 16239 hybrid_clock.cc:648] HybridClock initialized: now 1786515493357102 us; error 0 us; skew 500 ppm
I20260812 06:18:13.358098 16239 webserver.cc:533] Webserver started at http://127.15.219.254:37461/ using document root <none> and password file <none>
I20260812 06:18:13.358258 16239 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:13.358305 16239 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:13.358369 16239 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:13.358860 16239 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/master-0-root/instance:
uuid: "abd429955eef4e388edbfb59ca1ce9fe"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-bt4h"
I20260812 06:18:13.360527 16239 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:13.361522 16462 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:13.361794 16239 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:13.361897 16239 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/master-0-root
uuid: "abd429955eef4e388edbfb59ca1ce9fe"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-bt4h"
I20260812 06:18:13.361994 16239 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:13.397734 16239 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:13.398234 16239 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:13.402913 16239 rpc_server.cc:307] RPC server started. Bound to: 127.15.219.254:42377
I20260812 06:18:13.414404 16525 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.219.254:42377 every 8 connection(s)
I20260812 06:18:13.414966 16526 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:13.416810 16526 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe: Bootstrap starting.
I20260812 06:18:13.417579 16526 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:13.418637 16526 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe: No bootstrap required, opened a new log
I20260812 06:18:13.418989 16526 raft_consensus.cc:359] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abd429955eef4e388edbfb59ca1ce9fe" member_type: VOTER }
I20260812 06:18:13.419070 16526 raft_consensus.cc:385] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:13.419092 16526 raft_consensus.cc:740] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: abd429955eef4e388edbfb59ca1ce9fe, State: Initialized, Role: FOLLOWER
I20260812 06:18:13.419288 16526 consensus_queue.cc:260] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [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: "abd429955eef4e388edbfb59ca1ce9fe" member_type: VOTER }
I20260812 06:18:13.419382 16526 raft_consensus.cc:399] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:13.419407 16526 raft_consensus.cc:493] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:13.419437 16526 raft_consensus.cc:3060] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:13.420066 16526 raft_consensus.cc:515] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abd429955eef4e388edbfb59ca1ce9fe" member_type: VOTER }
I20260812 06:18:13.420176 16526 leader_election.cc:304] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [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: abd429955eef4e388edbfb59ca1ce9fe; no voters: 
I20260812 06:18:13.420328 16526 leader_election.cc:290] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:13.420471 16529 raft_consensus.cc:2804] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:13.420689 16529 raft_consensus.cc:697] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 1 LEADER]: Becoming Leader. State: Replica: abd429955eef4e388edbfb59ca1ce9fe, State: Running, Role: LEADER
I20260812 06:18:13.420771 16526 sys_catalog.cc:565] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:13.420853 16529 consensus_queue.cc:237] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [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: "abd429955eef4e388edbfb59ca1ce9fe" member_type: VOTER }
I20260812 06:18:13.421327 16531 sys_catalog.cc:455] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [sys.catalog]: SysCatalogTable state changed. Reason: New leader abd429955eef4e388edbfb59ca1ce9fe. Latest consensus state: current_term: 1 leader_uuid: "abd429955eef4e388edbfb59ca1ce9fe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abd429955eef4e388edbfb59ca1ce9fe" member_type: VOTER } }
I20260812 06:18:13.421428 16531 sys_catalog.cc:458] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:13.421316 16530 sys_catalog.cc:455] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "abd429955eef4e388edbfb59ca1ce9fe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abd429955eef4e388edbfb59ca1ce9fe" member_type: VOTER } }
I20260812 06:18:13.421495 16530 sys_catalog.cc:458] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:13.421717 16535 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:13.422642 16535 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:13.423534 16239 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:13.424680 16535 catalog_manager.cc:1383] Generated new cluster ID: 32d35b9edfa3481fa08c3cd3968034a9
I20260812 06:18:13.424742 16535 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:13.436293 16535 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:13.436964 16535 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:13.450340 16535 catalog_manager.cc:6092] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe: Generated new TSK 0
I20260812 06:18:13.450613 16535 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:13.456033 16239 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:13.458122 16549 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:13.458186 16550 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:13.458288 16552 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:13.458431 16239 server_base.cc:1061] running on GCE node
I20260812 06:18:13.458732 16239 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:13.458779 16239 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:13.458796 16239 hybrid_clock.cc:648] HybridClock initialized: now 1786515493458796 us; error 0 us; skew 500 ppm
I20260812 06:18:13.459719 16239 webserver.cc:533] Webserver started at http://127.15.219.193:33147/ using document root <none> and password file <none>
I20260812 06:18:13.459896 16239 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:13.459945 16239 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:13.460024 16239 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:13.460451 16239 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/instance:
uuid: "54212c42fc244859b41e88234b594c2d"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-bt4h"
I20260812 06:18:13.462075 16239 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:13.463173 16557 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:13.463505 16239 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:13.463590 16239 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root
uuid: "54212c42fc244859b41e88234b594c2d"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-bt4h"
I20260812 06:18:13.463657 16239 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:13.475845 16239 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:13.476254 16239 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:13.476547 16239 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:13.477090 16239 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:13.477133 16239 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:13.477212 16239 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:13.477257 16239 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:13.482367 16239 rpc_server.cc:307] RPC server started. Bound to: 127.15.219.193:34815
I20260812 06:18:13.484702 16630 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.219.193:34815 every 8 connection(s)
I20260812 06:18:13.494140 16631 heartbeater.cc:344] Connected to a master server at 127.15.219.254:42377
I20260812 06:18:13.494333 16631 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:13.494717 16631 heartbeater.cc:507] Master 127.15.219.254:42377 requested a full tablet report, sending...
I20260812 06:18:13.495577 16483 ts_manager.cc:194] Registered new tserver with Master: 54212c42fc244859b41e88234b594c2d (127.15.219.193:34815)
I20260812 06:18:13.495755 16239 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012237996s
I20260812 06:18:13.496429 16483 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33252
I20260812 06:18:13.503803 16483 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33260:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:13.513358 16589 tablet_service.cc:1511] Processing CreateTablet for tablet d6849ce2bb4d4c8c83c7d3c5f0f43b80 (DEFAULT_TABLE table=heavy-update-compaction-test [id=aaaf30c4fc254c14999a22568b9cf4e5]), partition=
I20260812 06:18:13.513674 16589 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d6849ce2bb4d4c8c83c7d3c5f0f43b80. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:13.515998 16646 tablet_bootstrap.cc:492] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Bootstrap starting.
I20260812 06:18:13.516881 16646 tablet_bootstrap.cc:654] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:13.518038 16646 tablet_bootstrap.cc:492] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: No bootstrap required, opened a new log
I20260812 06:18:13.518146 16646 ts_tablet_manager.cc:1403] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:13.518743 16646 raft_consensus.cc:359] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "54212c42fc244859b41e88234b594c2d" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 34815 } }
I20260812 06:18:13.518877 16646 raft_consensus.cc:385] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:13.518934 16646 raft_consensus.cc:740] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 54212c42fc244859b41e88234b594c2d, State: Initialized, Role: FOLLOWER
I20260812 06:18:13.519095 16646 consensus_queue.cc:260] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [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: "54212c42fc244859b41e88234b594c2d" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 34815 } }
I20260812 06:18:13.519197 16646 raft_consensus.cc:399] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:13.519241 16646 raft_consensus.cc:493] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:13.519291 16646 raft_consensus.cc:3060] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:13.520267 16646 raft_consensus.cc:515] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "54212c42fc244859b41e88234b594c2d" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 34815 } }
I20260812 06:18:13.520422 16646 leader_election.cc:304] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [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: 54212c42fc244859b41e88234b594c2d; no voters: 
I20260812 06:18:13.520661 16646 leader_election.cc:290] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:13.520874 16649 raft_consensus.cc:2804] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:13.521051 16646 ts_tablet_manager.cc:1434] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:13.521111 16649 raft_consensus.cc:697] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 1 LEADER]: Becoming Leader. State: Replica: 54212c42fc244859b41e88234b594c2d, State: Running, Role: LEADER
I20260812 06:18:13.521152 16631 heartbeater.cc:499] Master 127.15.219.254:42377 was elected leader, sending a full tablet report...
I20260812 06:18:13.521261 16649 consensus_queue.cc:237] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [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: "54212c42fc244859b41e88234b594c2d" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 34815 } }
I20260812 06:18:13.522840 16483 catalog_manager.cc:5719] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d reported cstate change: term changed from 0 to 1, leader changed from <none> to 54212c42fc244859b41e88234b594c2d (127.15.219.193). New cstate: current_term: 1 leader_uuid: "54212c42fc244859b41e88234b594c2d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "54212c42fc244859b41e88234b594c2d" member_type: VOTER last_known_addr { host: "127.15.219.193" port: 34815 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:13.594709 16239 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.014s	sys 0.017s
I20260812 06:18:13.735102 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=19.054940
I20260812 06:18:13.902573 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.167s	user 0.094s	sys 0.067s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":821,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45552,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:13.903164 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): free 20743880 bytes of WAL
I20260812 06:18:13.903399 16563 log_reader.cc:385] T d6849ce2bb4d4c8c83c7d3c5f0f43b80: removed 2 log segments from log reader
I20260812 06:18:13.903445 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000001 (ops 1-6)
I20260812 06:18:13.903475 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000002 (ops 7-11)
I20260812 06:18:13.907967 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:13.908361 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:13.924038 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.924647 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): 16411394 bytes on disk
I20260812 06:18:13.925242 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:18:13.925740 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:14.075904 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.150s	user 0.106s	sys 0.043s 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":246,"lbm_read_time_us":11269,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28034,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":319,"threads_started":5,"update_count":2000}
I20260812 06:18:14.076516 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=11.118625
I20260812 06:18:14.123688 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.047s	user 0.027s	sys 0.019s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":21691,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:14.124176 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:14.150957 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.027s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.151378 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:14.161556 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3920,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:14.162005 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:14.363582 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.201s	user 0.132s	sys 0.067s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":354,"lbm_read_time_us":14146,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36761,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":66816,"update_count":2500}
I20260812 06:18:14.364156 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=14.095187
I20260812 06:18:14.426893 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.063s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20387,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.427565 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:14.439980 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.440781 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:14.638441 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.197s	user 0.110s	sys 0.078s 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":663,"lbm_read_time_us":15794,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33968,"lbm_writes_lt_1ms":543,"mutex_wait_us":364,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2500}
I20260812 06:18:14.639062 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=14.095187
I20260812 06:18:14.701224 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.062s	user 0.032s	sys 0.026s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23023,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.701735 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:14.712642 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.713169 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:14.915992 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.203s	user 0.107s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":13687,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34514,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:14.916667 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=14.095187
I20260812 06:18:14.970680 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.054s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20049,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.971294 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:14.995601 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.024s	user 0.009s	sys 0.014s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4335,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.996236 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:15.196221 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.200s	user 0.108s	sys 0.091s 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":170,"lbm_read_time_us":15223,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32433,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":80128,"update_count":2500}
I20260812 06:18:15.196875 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=14.095187
I20260812 06:18:15.245940 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.049s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20649,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.246408 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:15.272966 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.026s	user 0.007s	sys 0.016s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:18:15.273645 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:15.330049 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.056s	user 0.041s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1166,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2269,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:15.331131 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=3.181125
I20260812 06:18:15.348863 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.017s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4860,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:15.349344 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): free 124710291 bytes of WAL
I20260812 06:18:15.349575 16563 log_reader.cc:385] T d6849ce2bb4d4c8c83c7d3c5f0f43b80: removed 12 log segments from log reader
I20260812 06:18:15.349630 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000003 (ops 12-16)
I20260812 06:18:15.349661 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000004 (ops 17-21)
I20260812 06:18:15.349726 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000005 (ops 22-26)
I20260812 06:18:15.349778 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000006 (ops 27-31)
I20260812 06:18:15.349822 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000007 (ops 32-36)
I20260812 06:18:15.349843 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000008 (ops 37-41)
I20260812 06:18:15.349896 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000009 (ops 42-46)
I20260812 06:18:15.349936 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000010 (ops 47-51)
I20260812 06:18:15.349973 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000011 (ops 52-56)
I20260812 06:18:15.350014 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000012 (ops 57-61)
I20260812 06:18:15.350054 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000013 (ops 62-66)
I20260812 06:18:15.350090 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000014 (ops 67-71)
I20260812 06:18:15.380244 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.031s	user 0.003s	sys 0.026s Metrics: {}
I20260812 06:18:15.380725 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:15.392386 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.392776 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:15.402724 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3862,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.403117 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): 472 bytes on disk
I20260812 06:18:15.403548 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:15.403972 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:15.662117 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.258s	user 0.165s	sys 0.092s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":791,"lbm_read_time_us":19690,"lbm_reads_lt_1ms":875,"lbm_write_time_us":48462,"lbm_writes_lt_1ms":843,"mutex_wait_us":348,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":84,"threads_started":1,"update_count":4000}
I20260812 06:18:15.662837 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=18.063937
I20260812 06:18:15.724602 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.062s	user 0.033s	sys 0.026s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27394,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:15.725399 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:15.738300 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.738772 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:15.902311 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.163s	user 0.125s	sys 0.038s 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":243,"lbm_read_time_us":11564,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32549,"lbm_writes_lt_1ms":643,"mutex_wait_us":66,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:18:15.903043 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=14.095187
I20260812 06:18:15.968452 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.065s	user 0.044s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":30133,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.968962 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:15.989717 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.021s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.990195 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:16.001160 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.001639 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:16.195904 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.194s	user 0.158s	sys 0.031s 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":994,"lbm_read_time_us":13360,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38876,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":3000}
I20260812 06:18:16.196669 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=14.095187
I20260812 06:18:16.261068 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.064s	user 0.030s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28899,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.261824 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:16.278620 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.279089 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:16.442778 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.163s	user 0.116s	sys 0.044s 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":2985,"lbm_read_time_us":13119,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30831,"lbm_writes_lt_1ms":543,"mutex_wait_us":1819,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:16.444516 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=13.103000
I20260812 06:18:16.494275 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.050s	user 0.037s	sys 0.009s Metrics: {"bytes_written":14727912,"delete_count":0,"lbm_write_time_us":22479,"lbm_writes_lt_1ms":362,"reinsert_count":0,"update_count":1795}
I20260812 06:18:16.494999 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:16.508143 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.013s	user 0.006s	sys 0.002s Metrics: {"bytes_written":1969356,"delete_count":0,"lbm_write_time_us":3396,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:18:16.508734 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:16.661798 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.153s	user 0.080s	sys 0.064s Metrics: {"cfile_cache_miss":439,"cfile_cache_miss_bytes":20959397,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1007,"lbm_read_time_us":11240,"lbm_reads_lt_1ms":471,"lbm_write_time_us":24694,"lbm_writes_lt_1ms":450,"mutex_wait_us":332,"peak_mem_usage":50976573,"reinsert_count":0,"update_count":2035}
I20260812 06:18:16.662385 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=14.095187
I20260812 06:18:16.709422 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.047s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16122742,"delete_count":0,"lbm_write_time_us":20558,"lbm_writes_lt_1ms":396,"reinsert_count":0,"update_count":1965}
I20260812 06:18:16.709954 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:16.734308 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.024s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.734911 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:16.772401 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.037s	user 0.016s	sys 0.008s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1298,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1936,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":896}
I20260812 06:18:16.773103 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): free 111786279 bytes of WAL
I20260812 06:18:16.773352 16563 log_reader.cc:385] T d6849ce2bb4d4c8c83c7d3c5f0f43b80: removed 11 log segments from log reader
I20260812 06:18:16.773414 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000015 (ops 72-76)
I20260812 06:18:16.773471 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000016 (ops 77-81)
I20260812 06:18:16.773511 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000017 (ops 82-86)
I20260812 06:18:16.773546 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000018 (ops 87-91)
I20260812 06:18:16.773583 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000019 (ops 92-96)
I20260812 06:18:16.773623 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000020 (ops 97-101)
I20260812 06:18:16.773664 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000021 (ops 102-106)
I20260812 06:18:16.773703 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000022 (ops 107-110)
I20260812 06:18:16.773752 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000023 (ops 111-115)
I20260812 06:18:16.773788 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000024 (ops 116-120)
I20260812 06:18:16.773829 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000025 (ops 121-124)
I20260812 06:18:16.799373 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:16.800010 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): 448 bytes on disk
I20260812 06:18:16.800638 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.801316 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:16.818956 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.819466 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:16.830507 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.831162 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:17.084766 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.253s	user 0.145s	sys 0.107s Metrics: {"cfile_cache_miss":727,"cfile_cache_miss_bytes":32692590,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1125,"lbm_read_time_us":17039,"lbm_reads_lt_1ms":767,"lbm_write_time_us":41544,"lbm_writes_lt_1ms":736,"mutex_wait_us":417,"peak_mem_usage":86641415,"reinsert_count":0,"spinlock_wait_cycles":47744,"thread_start_us":82,"threads_started":1,"update_count":3465}
I20260812 06:18:17.085700 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=18.063937
I20260812 06:18:17.153167 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.067s	user 0.049s	sys 0.011s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28923,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:17.153707 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:17.166409 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4481,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.166932 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:17.384682 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.218s	user 0.132s	sys 0.084s 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":1083,"lbm_read_time_us":16556,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35604,"lbm_writes_lt_1ms":643,"mutex_wait_us":303,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":3000}
I20260812 06:18:17.385502 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=18.063937
I20260812 06:18:17.460707 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.075s	user 0.039s	sys 0.032s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":33615,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:17.461246 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:17.474282 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4615,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.475335 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:17.700116 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.225s	user 0.125s	sys 0.087s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1262,"lbm_read_time_us":16370,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32763,"lbm_writes_lt_1ms":643,"mutex_wait_us":328,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":3000}
I20260812 06:18:17.700881 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=18.063937
I20260812 06:18:17.771581 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.070s	user 0.039s	sys 0.028s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":32460,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:17.772140 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:17.784097 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4435,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.784610 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:17.996047 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.211s	user 0.118s	sys 0.088s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1056,"lbm_read_time_us":15027,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35682,"lbm_writes_lt_1ms":643,"mutex_wait_us":305,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":3000}
I20260812 06:18:17.996892 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=16.079562
I20260812 06:18:18.054687 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.058s	user 0.044s	sys 0.008s Metrics: {"bytes_written":17968821,"delete_count":0,"lbm_write_time_us":23349,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:18:18.055285 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.196750
I20260812 06:18:18.070390 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":2953959,"delete_count":0,"lbm_write_time_us":5204,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:18:18.070966 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:18.081712 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.082216 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:18.295110 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.213s	user 0.165s	sys 0.043s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877185,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":619,"lbm_read_time_us":16452,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33119,"lbm_writes_lt_1ms":643,"mutex_wait_us":286,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3000}
I20260812 06:18:18.295917 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=16.079562
I20260812 06:18:18.352236 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.056s	user 0.031s	sys 0.020s Metrics: {"bytes_written":17804726,"delete_count":0,"lbm_write_time_us":23624,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2170}
I20260812 06:18:18.352854 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.196750
I20260812 06:18:18.362849 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3306,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:18.363382 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=2.188937
I20260812 06:18:18.373471 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.373934 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:18.408736 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushMRSOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1409,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1877,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":3328}
I20260812 06:18:18.409385 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): free 129773824 bytes of WAL
I20260812 06:18:18.409622 16563 log_reader.cc:385] T d6849ce2bb4d4c8c83c7d3c5f0f43b80: removed 13 log segments from log reader
I20260812 06:18:18.409672 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000026 (ops 125-129)
I20260812 06:18:18.409726 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000027 (ops 130-134)
I20260812 06:18:18.409771 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000028 (ops 135-139)
I20260812 06:18:18.409818 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000029 (ops 140-144)
I20260812 06:18:18.409859 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000030 (ops 145-149)
I20260812 06:18:18.409914 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000031 (ops 150-154)
I20260812 06:18:18.409952 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000032 (ops 155-158)
I20260812 06:18:18.409991 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000033 (ops 159-163)
I20260812 06:18:18.410027 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000034 (ops 164-168)
I20260812 06:18:18.410065 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000035 (ops 169-173)
I20260812 06:18:18.410112 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000036 (ops 174-178)
I20260812 06:18:18.410151 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000037 (ops 179-183)
I20260812 06:18:18.410188 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000038 (ops 184-188)
I20260812 06:18:18.442035 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:18.442641 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): 491 bytes on disk
I20260812 06:18:18.443142 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: UndoDeltaBlockGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.443813 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=5.165500
I20260812 06:18:18.462494 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":7138449,"delete_count":0,"lbm_write_time_us":7704,"lbm_writes_lt_1ms":177,"reinsert_count":0,"update_count":870}
I20260812 06:18:18.463388 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): free 11564900 bytes of WAL
I20260812 06:18:18.463644 16563 log_reader.cc:385] T d6849ce2bb4d4c8c83c7d3c5f0f43b80: removed 1 log segments from log reader
I20260812 06:18:18.463718 16563 log.cc:1079] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: Deleting log segment in path: /tmp/dist-test-taskVBpfUU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515487505912-16239-0/minicluster-data/ts-0-root/wals/d6849ce2bb4d4c8c83c7d3c5f0f43b80/wal-000000039 (ops 189-192)
I20260812 06:18:18.466768 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: LogGCOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:18.467115 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:18.652107 16239 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.057s	user 1.871s	sys 0.143s
I20260812 06:18:18.699903 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.233s	user 0.177s	sys 0.054s Metrics: {"cfile_cache_miss":808,"cfile_cache_miss_bytes":36015505,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":20367,"lbm_reads_lt_1ms":840,"lbm_write_time_us":40345,"lbm_writes_lt_1ms":817,"peak_mem_usage":97247938,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":3870}
I20260812 06:18:18.700405 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=15.087375
I20260812 06:18:18.741108 16239 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.089s	user 0.002s	sys 0.000s
I20260812 06:18:18.741637 16239 tablet_server.cc:179] TabletServer@127.15.219.193:0 shutting down...
I20260812 06:18:18.745999 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: FlushDeltaMemStoresOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.045s	user 0.029s	sys 0.008s Metrics: {"bytes_written":17476537,"delete_count":0,"lbm_write_time_us":17812,"lbm_writes_lt_1ms":429,"reinsert_count":0,"update_count":2130}
I20260812 06:18:18.746811 16632 maintenance_manager.cc:419] P 54212c42fc244859b41e88234b594c2d: Scheduling MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80): perf score=1.000000
I20260812 06:18:18.856950 16563 maintenance_manager.cc:643] P 54212c42fc244859b41e88234b594c2d: MajorDeltaCompactionOp(d6849ce2bb4d4c8c83c7d3c5f0f43b80) complete. Timing: real 0.110s	user 0.079s	sys 0.030s Metrics: {"cfile_cache_miss":457,"cfile_cache_miss_bytes":21738793,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":899,"lbm_read_time_us":7853,"lbm_reads_lt_1ms":493,"lbm_write_time_us":23251,"lbm_writes_lt_1ms":469,"mutex_wait_us":325,"peak_mem_usage":53837006,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2130}
I20260812 06:18:18.857607 16239 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:18.857867 16239 tablet_replica.cc:333] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d: stopping tablet replica
I20260812 06:18:18.858018 16239 raft_consensus.cc:2243] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:18.858191 16239 raft_consensus.cc:2272] T d6849ce2bb4d4c8c83c7d3c5f0f43b80 P 54212c42fc244859b41e88234b594c2d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:18.862165 16239 tablet_server.cc:196] TabletServer@127.15.219.193:0 shutdown complete.
I20260812 06:18:18.899485 16239 master.cc:562] Master@127.15.219.254:42377 shutting down...
I20260812 06:18:18.902685 16239 raft_consensus.cc:2243] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:18.902884 16239 raft_consensus.cc:2272] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:18.902968 16239 tablet_replica.cc:333] T 00000000000000000000000000000000 P abd429955eef4e388edbfb59ca1ce9fe: stopping tablet replica
I20260812 06:18:18.915405 16239 master.cc:584] Master@127.15.219.254:42377 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5653 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11491 ms total)

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