[==========] 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:19:05.288533 27181 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.139.126:36777
I20260812 06:19:05.289546 27181 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:19:05.290149 27181 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:05.296579 27191 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:05.296675 27181 server_base.cc:1061] running on GCE node
W20260812 06:19:05.296579 27194 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:19:05.296844 27192 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:19:05.297396 27181 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.297519 27181 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:19:05.297565 27181 hybrid_clock.cc:648] HybridClock initialized: now 1786515545297562 us; error 0 us; skew 500 ppm
I20260812 06:19:05.299280 27181 webserver.cc:533] Webserver started at http://127.26.139.126:40937/ using document root <none> and password file <none>
I20260812 06:19:05.299808 27181 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.299890 27181 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.300144 27181 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.301822 27181 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/master-0-root/instance:
uuid: "b9ca783502534a49ab918bc4446aa6ee"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-j2vl"
I20260812 06:19:05.305083 27181 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:05.307166 27206 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:19:05.308115 27181 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:05.308239 27181 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/master-0-root
uuid: "b9ca783502534a49ab918bc4446aa6ee"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-j2vl"
I20260812 06:19:05.308351 27181 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-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:19:05.322068 27181 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.322669 27181 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:19:05.322834 27181 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.331491 27181 rpc_server.cc:307] RPC server started. Bound to: 127.26.139.126:36777
I20260812 06:19:05.331489 27293 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.139.126:36777 every 8 connection(s)
I20260812 06:19:05.334394 27294 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:19:05.339792 27294 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee: Bootstrap starting.
I20260812 06:19:05.342084 27294 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.342901 27294 log.cc:826] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:05.344380 27294 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee: No bootstrap required, opened a new log
I20260812 06:19:05.347069 27294 raft_consensus.cc:359] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9ca783502534a49ab918bc4446aa6ee" member_type: VOTER }
I20260812 06:19:05.347224 27294 raft_consensus.cc:385] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.347272 27294 raft_consensus.cc:740] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b9ca783502534a49ab918bc4446aa6ee, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.347755 27294 consensus_queue.cc:260] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [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: "b9ca783502534a49ab918bc4446aa6ee" member_type: VOTER }
I20260812 06:19:05.347885 27294 raft_consensus.cc:399] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.347931 27294 raft_consensus.cc:493] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.348006 27294 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.348690 27294 raft_consensus.cc:515] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9ca783502534a49ab918bc4446aa6ee" member_type: VOTER }
I20260812 06:19:05.349040 27294 leader_election.cc:304] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [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: b9ca783502534a49ab918bc4446aa6ee; no voters: 
I20260812 06:19:05.349288 27294 leader_election.cc:290] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.349429 27301 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.349689 27301 raft_consensus.cc:697] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 1 LEADER]: Becoming Leader. State: Replica: b9ca783502534a49ab918bc4446aa6ee, State: Running, Role: LEADER
I20260812 06:19:05.350103 27301 consensus_queue.cc:237] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [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: "b9ca783502534a49ab918bc4446aa6ee" member_type: VOTER }
I20260812 06:19:05.350350 27294 sys_catalog.cc:565] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:05.351836 27303 sys_catalog.cc:455] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b9ca783502534a49ab918bc4446aa6ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9ca783502534a49ab918bc4446aa6ee" member_type: VOTER } }
I20260812 06:19:05.351892 27302 sys_catalog.cc:455] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [sys.catalog]: SysCatalogTable state changed. Reason: New leader b9ca783502534a49ab918bc4446aa6ee. Latest consensus state: current_term: 1 leader_uuid: "b9ca783502534a49ab918bc4446aa6ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9ca783502534a49ab918bc4446aa6ee" member_type: VOTER } }
I20260812 06:19:05.351953 27303 sys_catalog.cc:458] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.351991 27302 sys_catalog.cc:458] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.352269 27324 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:05.354372 27324 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:05.354610 27181 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:05.359000 27324 catalog_manager.cc:1383] Generated new cluster ID: 66b7ff3f0a1d49b6af9ea78ea8abced6
I20260812 06:19:05.359063 27324 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:05.371811 27324 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:05.373042 27324 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:05.382882 27324 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee: Generated new TSK 0
I20260812 06:19:05.383630 27324 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:05.387036 27181 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:05.389675 27348 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:19:05.389698 27344 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:19:05.389820 27342 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:05.389989 27181 server_base.cc:1061] running on GCE node
I20260812 06:19:05.390159 27181 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.390213 27181 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:19:05.390245 27181 hybrid_clock.cc:648] HybridClock initialized: now 1786515545390244 us; error 0 us; skew 500 ppm
I20260812 06:19:05.391124 27181 webserver.cc:533] Webserver started at http://127.26.139.65:34105/ using document root <none> and password file <none>
I20260812 06:19:05.391302 27181 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.391376 27181 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.391453 27181 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.391810 27181 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/instance:
uuid: "39a503cf49b949c2a715900b4de46346"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-j2vl"
I20260812 06:19:05.393296 27181 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:05.394354 27363 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:19:05.394608 27181 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:05.394696 27181 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root
uuid: "39a503cf49b949c2a715900b4de46346"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-j2vl"
I20260812 06:19:05.394795 27181 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-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:19:05.422142 27181 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.422608 27181 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.423123 27181 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:05.423938 27181 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:05.424033 27181 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.424117 27181 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:05.424172 27181 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.430866 27181 rpc_server.cc:307] RPC server started. Bound to: 127.26.139.65:39299
I20260812 06:19:05.430912 27485 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.139.65:39299 every 8 connection(s)
I20260812 06:19:05.443921 27490 heartbeater.cc:344] Connected to a master server at 127.26.139.126:36777
I20260812 06:19:05.444160 27490 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:05.444561 27490 heartbeater.cc:507] Master 127.26.139.126:36777 requested a full tablet report, sending...
I20260812 06:19:05.446005 27230 ts_manager.cc:194] Registered new tserver with Master: 39a503cf49b949c2a715900b4de46346 (127.26.139.65:39299)
I20260812 06:19:05.446214 27181 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014709275s
I20260812 06:19:05.447541 27230 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48504
I20260812 06:19:05.455302 27230 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48514:
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:19:05.468556 27416 tablet_service.cc:1511] Processing CreateTablet for tablet dd5bf587190c42c7a2368fb3fe922fea (DEFAULT_TABLE table=heavy-update-compaction-test [id=8b9942cf301641fe91504b99d08ce7d7]), partition=
I20260812 06:19:05.469030 27416 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dd5bf587190c42c7a2368fb3fe922fea. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:05.471132 27521 tablet_bootstrap.cc:492] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Bootstrap starting.
I20260812 06:19:05.472167 27521 tablet_bootstrap.cc:654] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.473296 27521 tablet_bootstrap.cc:492] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: No bootstrap required, opened a new log
I20260812 06:19:05.473412 27521 ts_tablet_manager.cc:1403] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:05.473910 27521 raft_consensus.cc:359] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "39a503cf49b949c2a715900b4de46346" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 39299 } }
I20260812 06:19:05.474032 27521 raft_consensus.cc:385] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.474078 27521 raft_consensus.cc:740] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 39a503cf49b949c2a715900b4de46346, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.474278 27521 consensus_queue.cc:260] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [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: "39a503cf49b949c2a715900b4de46346" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 39299 } }
I20260812 06:19:05.474383 27521 raft_consensus.cc:399] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.474429 27521 raft_consensus.cc:493] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.474475 27521 raft_consensus.cc:3060] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.475401 27521 raft_consensus.cc:515] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "39a503cf49b949c2a715900b4de46346" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 39299 } }
I20260812 06:19:05.475584 27521 leader_election.cc:304] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [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: 39a503cf49b949c2a715900b4de46346; no voters: 
I20260812 06:19:05.475795 27521 leader_election.cc:290] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.476146 27528 raft_consensus.cc:2804] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.476266 27521 ts_tablet_manager.cc:1434] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:05.476401 27528 raft_consensus.cc:697] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 1 LEADER]: Becoming Leader. State: Replica: 39a503cf49b949c2a715900b4de46346, State: Running, Role: LEADER
I20260812 06:19:05.476635 27490 heartbeater.cc:499] Master 127.26.139.126:36777 was elected leader, sending a full tablet report...
I20260812 06:19:05.476974 27528 consensus_queue.cc:237] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [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: "39a503cf49b949c2a715900b4de46346" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 39299 } }
I20260812 06:19:05.479429 27230 catalog_manager.cc:5719] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 reported cstate change: term changed from 0 to 1, leader changed from <none> to 39a503cf49b949c2a715900b4de46346 (127.26.139.65). New cstate: current_term: 1 leader_uuid: "39a503cf49b949c2a715900b4de46346" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "39a503cf49b949c2a715900b4de46346" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 39299 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:05.544364 27181 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.010s	sys 0.017s
I20260812 06:19:05.681989 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=19.054940
I20260812 06:19:05.863801 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.181s	user 0.114s	sys 0.064s Metrics: {"bytes_written":13661280,"cfile_init":1,"compiler_manager_pool.queue_time_us":201,"delete_count":0,"dirs.queue_time_us":39,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":728,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45861,"lbm_writes_lt_1ms":790,"mutex_wait_us":934,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":112128,"thread_start_us":134,"threads_started":1,"update_count":1665}
I20260812 06:19:05.865023 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling LogGCOp(dd5bf587190c42c7a2368fb3fe922fea): free 20743880 bytes of WAL
I20260812 06:19:05.865317 27372 log_reader.cc:385] T dd5bf587190c42c7a2368fb3fe922fea: removed 2 log segments from log reader
I20260812 06:19:05.865406 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000001 (ops 1-6)
I20260812 06:19:05.865463 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000002 (ops 7-11)
I20260812 06:19:05.870896 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: LogGCOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:05.871210 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea): 16411392 bytes on disk
I20260812 06:19:05.871852 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.872241 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=5.165500
I20260812 06:19:05.899430 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.027s	user 0.009s	sys 0.016s Metrics: {"bytes_written":6482069,"delete_count":0,"lbm_write_time_us":8848,"lbm_writes_lt_1ms":161,"reinsert_count":0,"update_count":790}
I20260812 06:19:05.899950 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:06.075135 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.175s	user 0.123s	sys 0.043s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405471,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":603,"lbm_read_time_us":12789,"lbm_reads_lt_1ms":555,"lbm_write_time_us":27884,"lbm_writes_lt_1ms":534,"peak_mem_usage":61706201,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":361,"threads_started":5,"update_count":2455}
I20260812 06:19:06.075802 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=15.087375
I20260812 06:19:06.125723 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.050s	user 0.011s	sys 0.028s Metrics: {"bytes_written":16779120,"delete_count":0,"lbm_write_time_us":17907,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2045}
I20260812 06:19:06.126278 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:06.136857 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.137429 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:06.322010 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.184s	user 0.099s	sys 0.069s Metrics: {"cfile_cache_miss":541,"cfile_cache_miss_bytes":25143907,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":151,"lbm_read_time_us":10679,"lbm_reads_lt_1ms":581,"lbm_write_time_us":27996,"lbm_writes_lt_1ms":552,"peak_mem_usage":63485215,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2545}
I20260812 06:19:06.322453 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:06.381201 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.059s	user 0.044s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26808,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.381752 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:06.392602 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.393097 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:06.557986 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.165s	user 0.118s	sys 0.035s 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":178,"lbm_read_time_us":10023,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33515,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:19:06.558717 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:06.612082 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.053s	user 0.042s	sys 0.009s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25607,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.612558 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:06.631992 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.632505 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:06.794169 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.162s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":379,"lbm_read_time_us":11273,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29597,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:19:06.794831 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:06.842787 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.048s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.843338 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:06.858419 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.858978 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:07.012866 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.154s	user 0.114s	sys 0.028s 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":289,"lbm_read_time_us":9086,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29140,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:07.013481 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:07.063530 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.050s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17919,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.064046 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:07.075102 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.075663 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:07.108306 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":157,"dirs.run_wall_time_us":1338,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1905,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:07.109212 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling LogGCOp(dd5bf587190c42c7a2368fb3fe922fea): free 120100345 bytes of WAL
I20260812 06:19:07.109488 27372 log_reader.cc:385] T dd5bf587190c42c7a2368fb3fe922fea: removed 12 log segments from log reader
I20260812 06:19:07.109543 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000003 (ops 12-16)
I20260812 06:19:07.109572 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000004 (ops 17-21)
I20260812 06:19:07.109591 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000005 (ops 22-26)
I20260812 06:19:07.109656 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000006 (ops 27-30)
I20260812 06:19:07.109700 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000007 (ops 31-35)
I20260812 06:19:07.109761 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000008 (ops 36-40)
I20260812 06:19:07.109805 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000009 (ops 41-45)
I20260812 06:19:07.109849 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000010 (ops 46-50)
I20260812 06:19:07.109885 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000011 (ops 51-54)
I20260812 06:19:07.109923 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000012 (ops 55-59)
I20260812 06:19:07.109963 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000013 (ops 60-64)
I20260812 06:19:07.110008 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000014 (ops 65-68)
I20260812 06:19:07.137035 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: LogGCOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.028s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:07.137526 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea): 473 bytes on disk
I20260812 06:19:07.138057 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea) 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:19:07.138603 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=3.181125
I20260812 06:19:07.150689 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4550,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:07.151098 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:07.164183 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4946,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.164738 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:07.350853 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.186s	user 0.132s	sys 0.054s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":773,"lbm_read_time_us":14902,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38892,"lbm_writes_lt_1ms":743,"mutex_wait_us":33,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:19:07.351678 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:07.402952 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.051s	user 0.037s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21342,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.403450 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:07.413554 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.413936 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:07.573772 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.160s	user 0.136s	sys 0.019s 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":315,"lbm_read_time_us":10164,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29622,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:07.574692 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=12.110812
I20260812 06:19:07.611569 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":13661280,"delete_count":0,"lbm_write_time_us":16198,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1665}
I20260812 06:19:07.612236 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.196750
I20260812 06:19:07.630162 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.018s	user 0.003s	sys 0.008s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:07.630730 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:07.778033 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.147s	user 0.105s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672238,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":136,"lbm_read_time_us":9738,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27510,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29568,"update_count":2000}
I20260812 06:19:07.778484 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:07.817814 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.039s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17046,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.818313 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:07.830440 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.830973 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:07.960098 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.129s	user 0.099s	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":455,"lbm_read_time_us":7631,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24787,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:19:07.960740 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:08.000113 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.039s	user 0.009s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14485,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.000800 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:08.011855 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.012506 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:08.127496 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.115s	user 0.094s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":406,"lbm_read_time_us":7121,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22032,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:08.130546 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:08.173023 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.042s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15438,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.173601 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:08.184060 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.184662 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:08.311239 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.126s	user 0.106s	sys 0.019s 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":165,"lbm_read_time_us":8914,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23942,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:08.312215 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:08.354447 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.042s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14680,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.354992 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:08.365067 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3904,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.365551 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:08.507440 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.142s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":11015,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23741,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:19:08.510458 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:08.544652 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.034s	user 0.022s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14538,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.545171 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:08.561786 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.562353 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:08.587723 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.025s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1570,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1731,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:08.588589 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling LogGCOp(dd5bf587190c42c7a2368fb3fe922fea): free 129320465 bytes of WAL
I20260812 06:19:08.588845 27372 log_reader.cc:385] T dd5bf587190c42c7a2368fb3fe922fea: removed 13 log segments from log reader
I20260812 06:19:08.588913 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000015 (ops 69-73)
I20260812 06:19:08.588965 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000016 (ops 74-78)
I20260812 06:19:08.589025 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000017 (ops 79-83)
I20260812 06:19:08.589071 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000018 (ops 84-88)
I20260812 06:19:08.589110 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000019 (ops 89-92)
I20260812 06:19:08.589148 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000020 (ops 93-97)
I20260812 06:19:08.589187 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000021 (ops 98-102)
I20260812 06:19:08.589227 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000022 (ops 103-107)
I20260812 06:19:08.589265 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000023 (ops 108-112)
I20260812 06:19:08.589304 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000024 (ops 113-117)
I20260812 06:19:08.589371 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000025 (ops 118-122)
I20260812 06:19:08.589421 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000026 (ops 123-126)
I20260812 06:19:08.589470 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000027 (ops 127-131)
I20260812 06:19:08.616255 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: LogGCOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:08.616725 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=3.181125
I20260812 06:19:08.634356 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7244,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:08.634860 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea): 482 bytes on disk
I20260812 06:19:08.635272 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:08.635860 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:08.652920 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.017s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3556,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.653471 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:08.858608 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.205s	user 0.120s	sys 0.081s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":499,"lbm_read_time_us":15566,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34184,"lbm_writes_lt_1ms":643,"mutex_wait_us":38,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7808,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:08.859359 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:08.920796 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.061s	user 0.037s	sys 0.014s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20453,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.921393 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:08.931654 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.932093 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:09.104592 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.172s	user 0.132s	sys 0.040s 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":284,"lbm_read_time_us":12522,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30102,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:09.105435 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:09.152500 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.047s	user 0.033s	sys 0.013s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":18957,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.153138 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:09.179239 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.026s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.179709 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:09.189659 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.190078 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:09.381072 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.191s	user 0.108s	sys 0.069s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774811,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":535,"lbm_read_time_us":13283,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27420,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:09.381945 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:09.430037 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19535,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.430580 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:09.445739 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.446308 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:09.600203 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.154s	user 0.122s	sys 0.028s 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":1080,"lbm_read_time_us":10318,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27926,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:09.600819 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=11.118625
I20260812 06:19:09.632339 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.031s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13271,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:09.633021 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:09.647362 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5273,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.647867 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:09.770376 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.122s	user 0.074s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":108,"lbm_read_time_us":7740,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24064,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:09.772109 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:09.814488 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.042s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14777,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.815120 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:09.825717 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.826361 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:09.951920 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.125s	user 0.100s	sys 0.024s 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":341,"lbm_read_time_us":9053,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23890,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:19:09.952754 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=10.126437
I20260812 06:19:10.002404 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.049s	user 0.020s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19272,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.002955 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:10.014096 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4233,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.014572 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:10.055388 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushMRSOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.041s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1346,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1845,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:10.056115 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling LogGCOp(dd5bf587190c42c7a2368fb3fe922fea): free 124257558 bytes of WAL
I20260812 06:19:10.056346 27372 log_reader.cc:385] T dd5bf587190c42c7a2368fb3fe922fea: removed 12 log segments from log reader
I20260812 06:19:10.056391 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000028 (ops 132-136)
I20260812 06:19:10.056420 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000029 (ops 137-141)
I20260812 06:19:10.056489 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000030 (ops 142-146)
I20260812 06:19:10.056533 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000031 (ops 147-151)
I20260812 06:19:10.056576 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000032 (ops 152-156)
I20260812 06:19:10.056639 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000033 (ops 157-161)
I20260812 06:19:10.056699 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000034 (ops 162-166)
I20260812 06:19:10.056738 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000035 (ops 167-170)
I20260812 06:19:10.056780 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000036 (ops 171-175)
I20260812 06:19:10.056816 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000037 (ops 176-180)
I20260812 06:19:10.056856 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000038 (ops 181-185)
I20260812 06:19:10.056896 27372 log.cc:1079] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/dd5bf587190c42c7a2368fb3fe922fea/wal-000000039 (ops 186-190)
I20260812 06:19:10.081018 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: LogGCOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:10.081459 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:10.096730 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.097230 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=2.188937
I20260812 06:19:10.107980 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.108639 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea): 462 bytes on disk
I20260812 06:19:10.109171 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: UndoDeltaBlockGCOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.109843 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:10.299644 27181 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.755s	user 1.789s	sys 0.087s
I20260812 06:19:10.317663 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.208s	user 0.118s	sys 0.088s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":574,"lbm_read_time_us":14767,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35133,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":744448,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:10.318418 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=14.095187
I20260812 06:19:10.354905 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: FlushDeltaMemStoresOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16463,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.355423 27492 maintenance_manager.cc:419] P 39a503cf49b949c2a715900b4de46346: Scheduling MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea): perf score=1.000000
I20260812 06:19:10.366953 27181 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.003s	sys 0.000s
I20260812 06:19:10.367604 27181 tablet_server.cc:179] TabletServer@127.26.139.65:0 shutting down...
I20260812 06:19:10.481007 27372 maintenance_manager.cc:643] P 39a503cf49b949c2a715900b4de46346: MajorDeltaCompactionOp(dd5bf587190c42c7a2368fb3fe922fea) complete. Timing: real 0.125s	user 0.095s	sys 0.029s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":401,"cfile_cache_miss_bytes":16409769,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":572,"lbm_read_time_us":7508,"lbm_reads_lt_1ms":413,"lbm_write_time_us":19428,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:19:10.481776 27181 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:10.482189 27181 tablet_replica.cc:333] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346: stopping tablet replica
I20260812 06:19:10.482425 27181 raft_consensus.cc:2243] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:10.482659 27181 raft_consensus.cc:2272] T dd5bf587190c42c7a2368fb3fe922fea P 39a503cf49b949c2a715900b4de46346 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:10.497468 27181 tablet_server.cc:196] TabletServer@127.26.139.65:0 shutdown complete.
I20260812 06:19:10.520088 27181 master.cc:562] Master@127.26.139.126:36777 shutting down...
I20260812 06:19:10.523887 27181 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:10.524091 27181 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:10.524201 27181 tablet_replica.cc:333] T 00000000000000000000000000000000 P b9ca783502534a49ab918bc4446aa6ee: stopping tablet replica
I20260812 06:19:10.537925 27181 master.cc:584] Master@127.26.139.126:36777 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5335 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:10.623143 27181 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.139.126:36971
I20260812 06:19:10.623553 27181 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:10.625912 27181 server_base.cc:1061] running on GCE node
W20260812 06:19:10.625983 27561 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:19:10.625962 27565 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:19:10.626206 27560 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:10.626418 27181 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:10.626459 27181 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:19:10.626487 27181 hybrid_clock.cc:648] HybridClock initialized: now 1786515550626486 us; error 0 us; skew 500 ppm
I20260812 06:19:10.627255 27181 webserver.cc:533] Webserver started at http://127.26.139.126:46693/ using document root <none> and password file <none>
I20260812 06:19:10.627384 27181 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:10.627425 27181 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:10.627483 27181 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:10.627818 27181 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/master-0-root/instance:
uuid: "c8343c74fc5344168e85a90b2fa9cda3"
format_stamp: "Formatted at 2026-08-12 06:19:10 on dist-test-slave-j2vl"
I20260812 06:19:10.629310 27181 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:10.630232 27579 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:19:10.630451 27181 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:10.630522 27181 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/master-0-root
uuid: "c8343c74fc5344168e85a90b2fa9cda3"
format_stamp: "Formatted at 2026-08-12 06:19:10 on dist-test-slave-j2vl"
I20260812 06:19:10.630575 27181 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-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:19:10.652529 27181 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:10.652904 27181 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:10.657142 27181 rpc_server.cc:307] RPC server started. Bound to: 127.26.139.126:36971
I20260812 06:19:10.659654 27675 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.139.126:36971 every 8 connection(s)
I20260812 06:19:10.660367 27677 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:19:10.670801 27677 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3: Bootstrap starting.
I20260812 06:19:10.671663 27677 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:10.672726 27677 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3: No bootstrap required, opened a new log
I20260812 06:19:10.673170 27677 raft_consensus.cc:359] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8343c74fc5344168e85a90b2fa9cda3" member_type: VOTER }
I20260812 06:19:10.673262 27677 raft_consensus.cc:385] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:10.673321 27677 raft_consensus.cc:740] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c8343c74fc5344168e85a90b2fa9cda3, State: Initialized, Role: FOLLOWER
I20260812 06:19:10.673555 27677 consensus_queue.cc:260] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [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: "c8343c74fc5344168e85a90b2fa9cda3" member_type: VOTER }
I20260812 06:19:10.673652 27677 raft_consensus.cc:399] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:10.673718 27677 raft_consensus.cc:493] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:10.673776 27677 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:10.674500 27677 raft_consensus.cc:515] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8343c74fc5344168e85a90b2fa9cda3" member_type: VOTER }
I20260812 06:19:10.674654 27677 leader_election.cc:304] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [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: c8343c74fc5344168e85a90b2fa9cda3; no voters: 
I20260812 06:19:10.674903 27677 leader_election.cc:290] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:10.675025 27682 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:10.675283 27682 raft_consensus.cc:697] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 1 LEADER]: Becoming Leader. State: Replica: c8343c74fc5344168e85a90b2fa9cda3, State: Running, Role: LEADER
I20260812 06:19:10.675395 27677 sys_catalog.cc:565] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:10.675416 27682 consensus_queue.cc:237] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [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: "c8343c74fc5344168e85a90b2fa9cda3" member_type: VOTER }
I20260812 06:19:10.675896 27686 sys_catalog.cc:455] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c8343c74fc5344168e85a90b2fa9cda3. Latest consensus state: current_term: 1 leader_uuid: "c8343c74fc5344168e85a90b2fa9cda3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8343c74fc5344168e85a90b2fa9cda3" member_type: VOTER } }
I20260812 06:19:10.675879 27684 sys_catalog.cc:455] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c8343c74fc5344168e85a90b2fa9cda3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8343c74fc5344168e85a90b2fa9cda3" member_type: VOTER } }
I20260812 06:19:10.676025 27686 sys_catalog.cc:458] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:10.676090 27684 sys_catalog.cc:458] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:10.676641 27693 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:10.677565 27693 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:10.677738 27181 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:10.679345 27693 catalog_manager.cc:1383] Generated new cluster ID: 8776d45794cb4397bea91eba1f40b7f2
I20260812 06:19:10.679392 27693 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:10.705214 27693 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:10.705835 27693 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:10.717222 27693 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3: Generated new TSK 0
I20260812 06:19:10.717458 27693 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:10.742519 27181 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:10.744570 27724 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:19:10.744625 27181 server_base.cc:1061] running on GCE node
W20260812 06:19:10.744675 27719 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:19:10.744589 27717 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:10.745010 27181 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:10.745055 27181 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:19:10.745071 27181 hybrid_clock.cc:648] HybridClock initialized: now 1786515550745071 us; error 0 us; skew 500 ppm
I20260812 06:19:10.745890 27181 webserver.cc:533] Webserver started at http://127.26.139.65:37003/ using document root <none> and password file <none>
I20260812 06:19:10.746044 27181 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:10.746095 27181 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:10.746150 27181 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:10.746519 27181 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/instance:
uuid: "2e8750aba8844a2cad0a81db375684a1"
format_stamp: "Formatted at 2026-08-12 06:19:10 on dist-test-slave-j2vl"
I20260812 06:19:10.747969 27181 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:10.748834 27736 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:19:10.749054 27181 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:10.749116 27181 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root
uuid: "2e8750aba8844a2cad0a81db375684a1"
format_stamp: "Formatted at 2026-08-12 06:19:10 on dist-test-slave-j2vl"
I20260812 06:19:10.749184 27181 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-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:19:10.767305 27181 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:10.767619 27181 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:10.767861 27181 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:10.768347 27181 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:10.768383 27181 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:10.768440 27181 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:10.768479 27181 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:10.773041 27181 rpc_server.cc:307] RPC server started. Bound to: 127.26.139.65:34673
I20260812 06:19:10.773062 27850 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.139.65:34673 every 8 connection(s)
I20260812 06:19:10.781728 27852 heartbeater.cc:344] Connected to a master server at 127.26.139.126:36971
I20260812 06:19:10.781828 27852 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:10.782032 27852 heartbeater.cc:507] Master 127.26.139.126:36971 requested a full tablet report, sending...
I20260812 06:19:10.782661 27611 ts_manager.cc:194] Registered new tserver with Master: 2e8750aba8844a2cad0a81db375684a1 (127.26.139.65:34673)
I20260812 06:19:10.783349 27611 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43716
I20260812 06:19:10.783478 27181 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009954172s
I20260812 06:19:10.790179 27611 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43730:
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:19:10.798288 27785 tablet_service.cc:1511] Processing CreateTablet for tablet 06ddb034c9074101875c0c0f2561632c (DEFAULT_TABLE table=heavy-update-compaction-test [id=4b83ebac3d82409788e7892a84dd537a]), partition=
I20260812 06:19:10.798563 27785 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 06ddb034c9074101875c0c0f2561632c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:10.800402 27874 tablet_bootstrap.cc:492] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Bootstrap starting.
I20260812 06:19:10.801299 27874 tablet_bootstrap.cc:654] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:10.802346 27874 tablet_bootstrap.cc:492] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: No bootstrap required, opened a new log
I20260812 06:19:10.802459 27874 ts_tablet_manager.cc:1403] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:10.802866 27874 raft_consensus.cc:359] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e8750aba8844a2cad0a81db375684a1" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 34673 } }
I20260812 06:19:10.802974 27874 raft_consensus.cc:385] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:10.803020 27874 raft_consensus.cc:740] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2e8750aba8844a2cad0a81db375684a1, State: Initialized, Role: FOLLOWER
I20260812 06:19:10.803191 27874 consensus_queue.cc:260] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [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: "2e8750aba8844a2cad0a81db375684a1" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 34673 } }
I20260812 06:19:10.803289 27874 raft_consensus.cc:399] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:10.803339 27874 raft_consensus.cc:493] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:10.803393 27874 raft_consensus.cc:3060] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:10.804306 27874 raft_consensus.cc:515] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e8750aba8844a2cad0a81db375684a1" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 34673 } }
I20260812 06:19:10.804458 27874 leader_election.cc:304] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [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: 2e8750aba8844a2cad0a81db375684a1; no voters: 
I20260812 06:19:10.804675 27874 leader_election.cc:290] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:10.804800 27878 raft_consensus.cc:2804] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:10.805008 27878 raft_consensus.cc:697] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 1 LEADER]: Becoming Leader. State: Replica: 2e8750aba8844a2cad0a81db375684a1, State: Running, Role: LEADER
I20260812 06:19:10.805025 27874 ts_tablet_manager.cc:1434] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:10.805029 27852 heartbeater.cc:499] Master 127.26.139.126:36971 was elected leader, sending a full tablet report...
I20260812 06:19:10.805155 27878 consensus_queue.cc:237] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [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: "2e8750aba8844a2cad0a81db375684a1" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 34673 } }
I20260812 06:19:10.806404 27611 catalog_manager.cc:5719] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2e8750aba8844a2cad0a81db375684a1 (127.26.139.65). New cstate: current_term: 1 leader_uuid: "2e8750aba8844a2cad0a81db375684a1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e8750aba8844a2cad0a81db375684a1" member_type: VOTER last_known_addr { host: "127.26.139.65" port: 34673 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:10.867573 27181 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.012s	sys 0.010s
I20260812 06:19:11.024008 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushMRSOp(06ddb034c9074101875c0c0f2561632c): perf score=19.054940
I20260812 06:19:11.172365 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushMRSOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.148s	user 0.110s	sys 0.035s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":997,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35888,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:11.173192 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling LogGCOp(06ddb034c9074101875c0c0f2561632c): free 20743880 bytes of WAL
I20260812 06:19:11.173456 27748 log_reader.cc:385] T 06ddb034c9074101875c0c0f2561632c: removed 2 log segments from log reader
I20260812 06:19:11.173557 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000001 (ops 1-6)
I20260812 06:19:11.173617 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000002 (ops 7-11)
I20260812 06:19:11.178954 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: LogGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:11.179334 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c): 16411395 bytes on disk
I20260812 06:19:11.180020 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:11.180403 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:11.203284 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.023s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.203905 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:11.214169 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.214727 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:11.367166 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.152s	user 0.105s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":603,"lbm_read_time_us":10848,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27560,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":327,"threads_started":5,"update_count":2500}
I20260812 06:19:11.367897 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:11.430365 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.062s	user 0.050s	sys 0.003s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.430898 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:11.446370 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.015s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.446925 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:11.584746 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.138s	user 0.108s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":82,"lbm_read_time_us":9815,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28359,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:19:11.585531 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=10.126437
I20260812 06:19:11.622699 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.037s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15938,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.623148 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:11.634290 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.635082 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:11.764446 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.129s	user 0.105s	sys 0.024s 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":163,"lbm_read_time_us":9880,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24149,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25600,"update_count":2000}
I20260812 06:19:11.765084 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=10.126437
I20260812 06:19:11.817317 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.052s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15047,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.817869 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:11.828181 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.828603 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:11.986783 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.158s	user 0.110s	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":263,"lbm_read_time_us":10676,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27081,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:19:11.987592 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=10.126437
I20260812 06:19:12.028475 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.041s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14570,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.029006 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:12.039472 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.039945 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:12.172091 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.132s	user 0.112s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":806,"lbm_read_time_us":9553,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23787,"lbm_writes_lt_1ms":443,"mutex_wait_us":187,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:19:12.172575 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=10.126437
I20260812 06:19:12.214613 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.042s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17581,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.215183 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:12.319335 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.104s	user 0.073s	sys 0.030s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1866,"lbm_read_time_us":6565,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19305,"lbm_writes_lt_1ms":343,"mutex_wait_us":525,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":1500}
I20260812 06:19:12.319903 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=10.126437
I20260812 06:19:12.361780 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.042s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17868,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.362309 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushMRSOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:12.401556 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushMRSOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.039s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1219,"drs_written":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1550,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:12.402756 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=3.181125
I20260812 06:19:12.418031 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4389828,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:19:12.418589 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling LogGCOp(06ddb034c9074101875c0c0f2561632c): free 120553374 bytes of WAL
I20260812 06:19:12.418826 27748 log_reader.cc:385] T 06ddb034c9074101875c0c0f2561632c: removed 12 log segments from log reader
I20260812 06:19:12.418895 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000003 (ops 12-16)
I20260812 06:19:12.418948 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000004 (ops 17-21)
I20260812 06:19:12.419016 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000005 (ops 22-26)
I20260812 06:19:12.419059 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000006 (ops 27-30)
I20260812 06:19:12.419095 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000007 (ops 31-35)
I20260812 06:19:12.419128 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000008 (ops 36-40)
I20260812 06:19:12.419164 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000009 (ops 41-44)
I20260812 06:19:12.419201 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000010 (ops 45-49)
I20260812 06:19:12.419237 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000011 (ops 50-54)
I20260812 06:19:12.419273 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000012 (ops 55-59)
I20260812 06:19:12.419310 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000013 (ops 60-64)
I20260812 06:19:12.419346 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000014 (ops 65-69)
I20260812 06:19:12.444993 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: LogGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:12.445417 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c): 463 bytes on disk
I20260812 06:19:12.446017 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:19:12.446480 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=3.181125
I20260812 06:19:12.461900 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":4564,"lbm_writes_lt_1ms":106,"reinsert_count":0,"update_count":515}
I20260812 06:19:12.462432 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:12.475523 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5171,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:12.475972 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:12.654485 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.178s	user 0.126s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":455,"lbm_read_time_us":12670,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30851,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:19:12.655184 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:12.704319 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.049s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21397,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.704921 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:12.723856 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.724305 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:12.862537 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.138s	user 0.105s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":767,"lbm_read_time_us":8945,"lbm_reads_lt_1ms":564,"lbm_write_time_us":24921,"lbm_writes_lt_1ms":543,"mutex_wait_us":252,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:12.863233 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:12.929319 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.066s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22297,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.929937 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:12.940621 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.941267 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:13.129534 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.188s	user 0.097s	sys 0.079s 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":328,"lbm_read_time_us":13241,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31721,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:19:13.130230 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:13.193082 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.063s	user 0.022s	sys 0.029s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22726,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.193569 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:13.210539 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.017s	user 0.014s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6575,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.211035 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:13.375861 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.165s	user 0.110s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":374,"lbm_read_time_us":11106,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28532,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:19:13.376389 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:13.435336 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.059s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22031,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.435916 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:13.446460 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.446889 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:13.613122 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.166s	user 0.117s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":12011,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25918,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:19:13.613881 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:13.669843 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.056s	user 0.020s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20995,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.670302 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:13.680977 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.681483 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:13.870333 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.189s	user 0.124s	sys 0.053s 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":781,"lbm_read_time_us":12711,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30215,"lbm_writes_lt_1ms":543,"mutex_wait_us":303,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:13.871024 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:13.924299 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.053s	user 0.037s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19526,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.924831 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:13.936761 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.938920 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushMRSOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:13.976678 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushMRSOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.038s	user 0.032s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1240,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1826,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:13.977291 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling LogGCOp(06ddb034c9074101875c0c0f2561632c): free 129320527 bytes of WAL
I20260812 06:19:13.977623 27748 log_reader.cc:385] T 06ddb034c9074101875c0c0f2561632c: removed 13 log segments from log reader
I20260812 06:19:13.977696 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000015 (ops 70-74)
I20260812 06:19:13.977735 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000016 (ops 75-79)
I20260812 06:19:13.977766 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000017 (ops 80-84)
I20260812 06:19:13.977797 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000018 (ops 85-88)
I20260812 06:19:13.977835 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000019 (ops 89-93)
I20260812 06:19:13.977869 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000020 (ops 94-98)
I20260812 06:19:13.977900 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000021 (ops 99-103)
I20260812 06:19:13.977929 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000022 (ops 104-108)
I20260812 06:19:13.977959 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000023 (ops 109-112)
I20260812 06:19:13.977990 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000024 (ops 113-117)
I20260812 06:19:13.978025 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000025 (ops 118-122)
I20260812 06:19:13.978058 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000026 (ops 123-127)
I20260812 06:19:13.978087 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000027 (ops 128-132)
I20260812 06:19:14.010298 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: LogGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.033s	user 0.004s	sys 0.028s Metrics: {}
I20260812 06:19:14.010727 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c): 492 bytes on disk
I20260812 06:19:14.011178 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.011688 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:14.034876 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.023s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4414,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.035367 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:14.045239 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.045691 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:14.285521 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.240s	user 0.187s	sys 0.050s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":264,"lbm_read_time_us":15101,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39517,"lbm_writes_lt_1ms":743,"mutex_wait_us":46,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18816,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:19:14.286327 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=18.063937
I20260812 06:19:14.354413 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.068s	user 0.047s	sys 0.012s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26782,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:14.354885 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:14.365509 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.366329 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:14.570696 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.204s	user 0.152s	sys 0.051s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":13987,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35612,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:19:14.571247 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:14.635923 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.064s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20395,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:14.636384 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:14.647442 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.647966 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:14.811880 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.164s	user 0.131s	sys 0.031s 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":149,"lbm_read_time_us":13610,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25517,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":164352,"update_count":2500}
I20260812 06:19:14.812574 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:14.861980 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.049s	user 0.041s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21269,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.862478 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:14.872907 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.875738 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:15.059723 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.184s	user 0.124s	sys 0.052s 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":306,"lbm_read_time_us":12973,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30674,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:15.060428 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:15.121702 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.061s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18725,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.122249 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:15.133028 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.133603 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:15.323489 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.190s	user 0.137s	sys 0.041s 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":291,"lbm_read_time_us":12962,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31410,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":661632,"update_count":2500}
I20260812 06:19:15.323956 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=14.095187
I20260812 06:19:15.375365 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.051s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":18280,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.375823 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:15.395896 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.396626 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushMRSOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:15.432267 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushMRSOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1391,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2132,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:15.432931 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling LogGCOp(06ddb034c9074101875c0c0f2561632c): free 115490363 bytes of WAL
I20260812 06:19:15.433183 27748 log_reader.cc:385] T 06ddb034c9074101875c0c0f2561632c: removed 11 log segments from log reader
I20260812 06:19:15.433229 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000028 (ops 133-136)
I20260812 06:19:15.433256 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000029 (ops 137-141)
I20260812 06:19:15.433316 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000030 (ops 142-146)
I20260812 06:19:15.433400 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000031 (ops 147-151)
I20260812 06:19:15.433439 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000032 (ops 152-156)
I20260812 06:19:15.433485 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000033 (ops 157-161)
I20260812 06:19:15.433527 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000034 (ops 162-166)
I20260812 06:19:15.433563 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000035 (ops 167-171)
I20260812 06:19:15.433604 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000036 (ops 172-176)
I20260812 06:19:15.433653 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000037 (ops 177-181)
I20260812 06:19:15.433694 27748 log.cc:1079] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: Deleting log segment in path: /tmp/dist-test-taskss41xH/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545278160-27181-0/minicluster-data/ts-0-root/wals/06ddb034c9074101875c0c0f2561632c/wal-000000038 (ops 182-186)
I20260812 06:19:15.457873 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: LogGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:15.458344 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:15.482370 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.482899 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=2.188937
I20260812 06:19:15.493040 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3941,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.493692 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c): 447 bytes on disk
I20260812 06:19:15.494365 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: UndoDeltaBlockGCOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":122,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.495110 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:15.724745 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.229s	user 0.142s	sys 0.085s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979754,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":341,"lbm_read_time_us":15766,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38254,"lbm_writes_lt_1ms":743,"mutex_wait_us":74,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23552,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:15.725718 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=16.079562
I20260812 06:19:15.736653 27181 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.869s	user 1.812s	sys 0.182s
I20260812 06:19:15.766484 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":17763699,"delete_count":0,"lbm_write_time_us":18332,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2165}
I20260812 06:19:15.767092 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c): perf score=1.196750
I20260812 06:19:15.776811 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: FlushDeltaMemStoresOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":2958,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:15.777328 27853 maintenance_manager.cc:419] P 2e8750aba8844a2cad0a81db375684a1: Scheduling MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c): perf score=1.000000
I20260812 06:19:15.777964 27181 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.041s	user 0.003s	sys 0.000s
I20260812 06:19:15.778434 27181 tablet_server.cc:179] TabletServer@127.26.139.65:0 shutting down...
I20260812 06:19:15.917587 27748 maintenance_manager.cc:643] P 2e8750aba8844a2cad0a81db375684a1: MajorDeltaCompactionOp(06ddb034c9074101875c0c0f2561632c) complete. Timing: real 0.140s	user 0.106s	sys 0.031s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512267,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":6609,"lbm_read_time_us":8030,"lbm_reads_lt_1ms":518,"lbm_write_time_us":23989,"lbm_writes_lt_1ms":543,"mutex_wait_us":2957,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:15.918612 27181 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:15.919305 27181 tablet_replica.cc:333] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1: stopping tablet replica
I20260812 06:19:15.919480 27181 raft_consensus.cc:2243] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:15.919690 27181 raft_consensus.cc:2272] T 06ddb034c9074101875c0c0f2561632c P 2e8750aba8844a2cad0a81db375684a1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:15.934952 27181 tablet_server.cc:196] TabletServer@127.26.139.65:0 shutdown complete.
I20260812 06:19:15.960395 27181 master.cc:562] Master@127.26.139.126:36971 shutting down...
I20260812 06:19:15.963783 27181 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:15.963937 27181 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:15.963991 27181 tablet_replica.cc:333] T 00000000000000000000000000000000 P c8343c74fc5344168e85a90b2fa9cda3: stopping tablet replica
I20260812 06:19:15.976230 27181 master.cc:584] Master@127.26.139.126:36971 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5438 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10774 ms total)

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