[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:57.983263 27385 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.190.126:39691
I20260812 06:18:57.984341 27385 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:57.985034 27385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:57.992041 27385 server_base.cc:1061] running on GCE node
W20260812 06:18:57.991971 27397 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:57.992002 27394 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:57.992338 27395 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:57.992973 27385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.993072 27385 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:57.993110 27385 hybrid_clock.cc:648] HybridClock initialized: now 1786515537993102 us; error 0 us; skew 500 ppm
I20260812 06:18:57.995050 27385 webserver.cc:533] Webserver started at http://127.26.190.126:44137/ using document root <none> and password file <none>
I20260812 06:18:57.995671 27385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.995745 27385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.995968 27385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.997867 27385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/master-0-root/instance:
uuid: "a4ee33acbbd04891a6cde536fa8d5ac7"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-g170"
I20260812 06:18:58.001688 27385 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:58.003847 27407 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.004989 27385 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:58.005118 27385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/master-0-root
uuid: "a4ee33acbbd04891a6cde536fa8d5ac7"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-g170"
I20260812 06:18:58.005224 27385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:58.024107 27385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:58.024945 27385 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:58.025146 27385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:58.039604 27385 rpc_server.cc:307] RPC server started. Bound to: 127.26.190.126:39691
I20260812 06:18:58.039601 27495 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.190.126:39691 every 8 connection(s)
I20260812 06:18:58.042068 27496 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:58.047608 27496 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7: Bootstrap starting.
I20260812 06:18:58.050110 27496 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:58.051057 27496 log.cc:826] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:58.052711 27496 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7: No bootstrap required, opened a new log
I20260812 06:18:58.055475 27496 raft_consensus.cc:359] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4ee33acbbd04891a6cde536fa8d5ac7" member_type: VOTER }
I20260812 06:18:58.055634 27496 raft_consensus.cc:385] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:58.055754 27496 raft_consensus.cc:740] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4ee33acbbd04891a6cde536fa8d5ac7, State: Initialized, Role: FOLLOWER
I20260812 06:18:58.056418 27496 consensus_queue.cc:260] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [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: "a4ee33acbbd04891a6cde536fa8d5ac7" member_type: VOTER }
I20260812 06:18:58.056593 27496 raft_consensus.cc:399] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:58.056684 27496 raft_consensus.cc:493] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:58.056849 27496 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:58.057641 27496 raft_consensus.cc:515] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4ee33acbbd04891a6cde536fa8d5ac7" member_type: VOTER }
I20260812 06:18:58.058084 27496 leader_election.cc:304] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [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: a4ee33acbbd04891a6cde536fa8d5ac7; no voters: 
I20260812 06:18:58.058422 27496 leader_election.cc:290] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:58.058512 27504 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:58.058724 27504 raft_consensus.cc:697] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 1 LEADER]: Becoming Leader. State: Replica: a4ee33acbbd04891a6cde536fa8d5ac7, State: Running, Role: LEADER
I20260812 06:18:58.059151 27504 consensus_queue.cc:237] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [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: "a4ee33acbbd04891a6cde536fa8d5ac7" member_type: VOTER }
I20260812 06:18:58.059473 27496 sys_catalog.cc:565] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:58.061467 27505 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a4ee33acbbd04891a6cde536fa8d5ac7. Latest consensus state: current_term: 1 leader_uuid: "a4ee33acbbd04891a6cde536fa8d5ac7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4ee33acbbd04891a6cde536fa8d5ac7" member_type: VOTER } }
I20260812 06:18:58.061486 27506 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a4ee33acbbd04891a6cde536fa8d5ac7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4ee33acbbd04891a6cde536fa8d5ac7" member_type: VOTER } }
I20260812 06:18:58.061633 27505 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:58.061643 27506 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:58.062016 27385 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:58.064178 27529 catalog_manager.cc:1594] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:58.064255 27529 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:58.064324 27526 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:58.065274 27526 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:58.069898 27526 catalog_manager.cc:1383] Generated new cluster ID: 71060e77e74f477fbac490540f81345d
I20260812 06:18:58.069959 27526 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:58.077864 27526 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:58.078823 27526 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:58.087834 27526 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7: Generated new TSK 0
I20260812 06:18:58.088563 27526 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:58.094501 27385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.097110 27533 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.097355 27534 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.097576 27539 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.098703 27385 server_base.cc:1061] running on GCE node
I20260812 06:18:58.098883 27385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.098938 27385 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:58.098973 27385 hybrid_clock.cc:648] HybridClock initialized: now 1786515538098971 us; error 0 us; skew 500 ppm
I20260812 06:18:58.099884 27385 webserver.cc:533] Webserver started at http://127.26.190.65:43897/ using document root <none> and password file <none>
I20260812 06:18:58.100070 27385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.100167 27385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.100278 27385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.100674 27385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/instance:
uuid: "d45eaef304f24800bea8337dcd8f4998"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-g170"
I20260812 06:18:58.102173 27385 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:58.103204 27546 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.103440 27385 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:58.103529 27385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root
uuid: "d45eaef304f24800bea8337dcd8f4998"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-g170"
I20260812 06:18:58.103612 27385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:58.112555 27385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:58.113008 27385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:58.113511 27385 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:58.114377 27385 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:58.114449 27385 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.114547 27385 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:58.114594 27385 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.121625 27385 rpc_server.cc:307] RPC server started. Bound to: 127.26.190.65:40157
I20260812 06:18:58.121673 27660 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.190.65:40157 every 8 connection(s)
I20260812 06:18:58.134672 27663 heartbeater.cc:344] Connected to a master server at 127.26.190.126:39691
I20260812 06:18:58.134979 27663 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:58.135536 27663 heartbeater.cc:507] Master 127.26.190.126:39691 requested a full tablet report, sending...
I20260812 06:18:58.137106 27441 ts_manager.cc:194] Registered new tserver with Master: d45eaef304f24800bea8337dcd8f4998 (127.26.190.65:40157)
I20260812 06:18:58.137238 27385 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014979978s
I20260812 06:18:58.138500 27441 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39806
I20260812 06:18:58.147763 27441 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39816:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:58.163172 27595 tablet_service.cc:1511] Processing CreateTablet for tablet 6c3f2b1055cd474e9c9aa2ae807bfbd3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f17d78ddc7c74a48b9fd78572f03fd84]), partition=
I20260812 06:18:58.163717 27595 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6c3f2b1055cd474e9c9aa2ae807bfbd3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:58.166424 27687 tablet_bootstrap.cc:492] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Bootstrap starting.
I20260812 06:18:58.167471 27687 tablet_bootstrap.cc:654] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:58.168696 27687 tablet_bootstrap.cc:492] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: No bootstrap required, opened a new log
I20260812 06:18:58.168843 27687 ts_tablet_manager.cc:1403] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:58.169307 27687 raft_consensus.cc:359] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d45eaef304f24800bea8337dcd8f4998" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 40157 } }
I20260812 06:18:58.169428 27687 raft_consensus.cc:385] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:58.169453 27687 raft_consensus.cc:740] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d45eaef304f24800bea8337dcd8f4998, State: Initialized, Role: FOLLOWER
I20260812 06:18:58.169653 27687 consensus_queue.cc:260] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [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: "d45eaef304f24800bea8337dcd8f4998" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 40157 } }
I20260812 06:18:58.169749 27687 raft_consensus.cc:399] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:58.169807 27687 raft_consensus.cc:493] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:58.169867 27687 raft_consensus.cc:3060] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:58.170886 27687 raft_consensus.cc:515] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d45eaef304f24800bea8337dcd8f4998" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 40157 } }
I20260812 06:18:58.171033 27687 leader_election.cc:304] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [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: d45eaef304f24800bea8337dcd8f4998; no voters: 
I20260812 06:18:58.171293 27687 leader_election.cc:290] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:58.171388 27689 raft_consensus.cc:2804] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:58.171579 27689 raft_consensus.cc:697] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 1 LEADER]: Becoming Leader. State: Replica: d45eaef304f24800bea8337dcd8f4998, State: Running, Role: LEADER
I20260812 06:18:58.171694 27687 ts_tablet_manager.cc:1434] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:58.171799 27689 consensus_queue.cc:237] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [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: "d45eaef304f24800bea8337dcd8f4998" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 40157 } }
I20260812 06:18:58.171901 27663 heartbeater.cc:499] Master 127.26.190.126:39691 was elected leader, sending a full tablet report...
I20260812 06:18:58.175252 27441 catalog_manager.cc:5719] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 reported cstate change: term changed from 0 to 1, leader changed from <none> to d45eaef304f24800bea8337dcd8f4998 (127.26.190.65). New cstate: current_term: 1 leader_uuid: "d45eaef304f24800bea8337dcd8f4998" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d45eaef304f24800bea8337dcd8f4998" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 40157 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:58.243057 27385 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.016s	sys 0.011s
I20260812 06:18:58.372742 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=15.086190
I20260812 06:18:58.512954 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.140s	user 0.091s	sys 0.049s Metrics: {"bytes_written":9189657,"cfile_init":1,"compiler_manager_pool.queue_time_us":234,"delete_count":0,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":799,"drs_written":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35617,"lbm_writes_lt_1ms":581,"mutex_wait_us":133,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":136960,"thread_start_us":131,"threads_started":1,"update_count":1120}
I20260812 06:18:58.513983 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): free 8725963 bytes of WAL
I20260812 06:18:58.514271 27551 log_reader.cc:385] T 6c3f2b1055cd474e9c9aa2ae807bfbd3: removed 1 log segments from log reader
I20260812 06:18:58.514343 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000001 (ops 1-6)
I20260812 06:18:58.516251 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:58.516552 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): 12308959 bytes on disk
I20260812 06:18:58.517315 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.517976 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.196750
I20260812 06:18:58.534256 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":5034,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:58.534747 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:58.656592 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.122s	user 0.074s	sys 0.036s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528875,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":570,"lbm_read_time_us":6484,"lbm_reads_lt_1ms":360,"lbm_write_time_us":21268,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":297,"threads_started":5,"update_count":1500}
I20260812 06:18:58.657184 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:18:58.705631 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.048s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":16572,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.706146 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:18:58.718060 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.718631 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:58.857498 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.139s	user 0.115s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631317,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":356,"lbm_read_time_us":9949,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26744,"lbm_writes_lt_1ms":443,"mutex_wait_us":82,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:58.858225 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:18:58.910164 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.052s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18188,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.910650 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:18:58.921029 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.921432 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:59.071544 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.150s	user 0.126s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":11081,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25078,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.072325 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=7.149875
I20260812 06:18:59.099546 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.027s	user 0.010s	sys 0.015s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11905,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:59.100077 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:18:59.112354 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.112843 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:59.224328 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.111s	user 0.100s	sys 0.009s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":7244,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21994,"lbm_writes_lt_1ms":343,"mutex_wait_us":76,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":1500}
I20260812 06:18:59.224997 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=7.149875
I20260812 06:18:59.245698 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.021s	user 0.011s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9013,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:59.246181 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:18:59.255769 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.256357 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:59.377040 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.120s	user 0.071s	sys 0.038s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":7368,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21338,"lbm_writes_lt_1ms":343,"mutex_wait_us":43,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":1500}
I20260812 06:18:59.377626 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:18:59.413820 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.036s	user 0.023s	sys 0.010s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14739,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.414386 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:59.532948 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.118s	user 0.083s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528780,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":176,"lbm_read_time_us":7663,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22610,"lbm_writes_lt_1ms":343,"mutex_wait_us":26,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":52992,"update_count":1500}
I20260812 06:18:59.535915 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:18:59.581082 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.045s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15926,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.581703 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:18:59.593456 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.594036 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:59.722693 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.128s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":435,"lbm_read_time_us":10253,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26392,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.723402 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:18:59.773125 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.049s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15371,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.773653 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:18:59.789536 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6325,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.790021 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:59.822244 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.032s	user 0.029s	sys 0.002s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1143,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1482,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:59.823036 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): 447 bytes on disk
I20260812 06:18:59.823429 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.823876 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:18:59.974754 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.151s	user 0.094s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":8761,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27172,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.975437 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): free 123804182 bytes of WAL
I20260812 06:18:59.975692 27551 log_reader.cc:385] T 6c3f2b1055cd474e9c9aa2ae807bfbd3: removed 12 log segments from log reader
I20260812 06:18:59.975783 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000002 (ops 7-11)
I20260812 06:18:59.975857 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000003 (ops 12-16)
I20260812 06:18:59.975909 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000004 (ops 17-21)
I20260812 06:18:59.975961 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000005 (ops 22-26)
I20260812 06:18:59.976006 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000006 (ops 27-31)
I20260812 06:18:59.976080 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000007 (ops 32-36)
I20260812 06:18:59.976145 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000008 (ops 37-40)
I20260812 06:18:59.976212 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000009 (ops 41-45)
I20260812 06:18:59.976253 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000010 (ops 46-50)
I20260812 06:18:59.976285 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000011 (ops 51-55)
I20260812 06:18:59.976325 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000012 (ops 56-60)
I20260812 06:18:59.976368 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000013 (ops 61-64)
I20260812 06:19:00.002920 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:00.003394 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=14.095187
I20260812 06:19:00.049355 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.046s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20694,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.049885 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:00.065196 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.065837 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:00.243350 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.177s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":89,"lbm_read_time_us":13788,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28459,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:19:00.244426 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=11.118625
I20260812 06:19:00.279291 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.035s	user 0.011s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15370,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:00.279915 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:00.297812 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.018s	user 0.007s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6564,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.298323 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:00.435091 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.137s	user 0.115s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":10776,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26099,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:00.439615 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:19:00.490432 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.049s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16049,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.490993 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:00.503393 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.504082 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:00.637152 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.133s	user 0.100s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":429,"lbm_read_time_us":11128,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24724,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:19:00.637893 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:19:00.695845 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.058s	user 0.019s	sys 0.033s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20635,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.696383 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:00.707013 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.707526 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:00.876892 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.169s	user 0.116s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":11839,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29760,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":44416,"update_count":2000}
I20260812 06:19:00.877615 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:19:00.926659 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.049s	user 0.012s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16774,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.927294 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:00.939273 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.939970 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:01.058130 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.118s	user 0.098s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":685,"lbm_read_time_us":9241,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22896,"lbm_writes_lt_1ms":443,"mutex_wait_us":319,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:19:01.058704 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:19:01.100694 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.042s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17875,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.101315 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:01.209228 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.108s	user 0.089s	sys 0.018s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1021,"lbm_read_time_us":8445,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19471,"lbm_writes_lt_1ms":343,"mutex_wait_us":2,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:19:01.210065 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:19:01.260450 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.050s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17052,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.261045 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:01.271528 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.271974 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:01.302896 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1388,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1484,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:01.303638 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): free 112692317 bytes of WAL
I20260812 06:19:01.303889 27551 log_reader.cc:385] T 6c3f2b1055cd474e9c9aa2ae807bfbd3: removed 11 log segments from log reader
I20260812 06:19:01.303936 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000014 (ops 65-69)
I20260812 06:19:01.303964 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000015 (ops 70-74)
I20260812 06:19:01.304028 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000016 (ops 75-79)
I20260812 06:19:01.304070 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000017 (ops 80-84)
I20260812 06:19:01.304108 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000018 (ops 85-89)
I20260812 06:19:01.304145 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000019 (ops 90-94)
I20260812 06:19:01.304185 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000020 (ops 95-99)
I20260812 06:19:01.304222 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000021 (ops 100-104)
I20260812 06:19:01.304262 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000022 (ops 105-109)
I20260812 06:19:01.304301 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000023 (ops 110-114)
I20260812 06:19:01.304339 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000024 (ops 115-119)
I20260812 06:19:01.330345 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:01.335580 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:01.359112 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.023s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.359552 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:01.370174 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.370613 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:01.577158 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.206s	user 0.110s	sys 0.090s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836372,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":741,"lbm_read_time_us":14959,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34858,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27648,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:19:01.577844 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): 447 bytes on disk
I20260812 06:19:01.578435 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.579581 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=14.095187
I20260812 06:19:01.658845 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.079s	user 0.038s	sys 0.031s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":26111,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.659466 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:01.677819 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.678536 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:01.857849 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.179s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":13761,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29108,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:01.858599 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=14.095187
I20260812 06:19:01.919732 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.061s	user 0.019s	sys 0.039s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22744,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.920334 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:01.931756 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4350,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.932286 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:02.109338 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.177s	user 0.109s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":13370,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30870,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:02.110008 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:19:02.155125 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.045s	user 0.015s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18344,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.155707 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:02.181612 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.026s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.182066 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:02.201218 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.019s	user 0.003s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.201651 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:02.400906 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.199s	user 0.123s	sys 0.075s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733842,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":328,"lbm_read_time_us":11220,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35387,"lbm_writes_lt_1ms":543,"mutex_wait_us":123,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:02.401531 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=10.126437
I20260812 06:19:02.451059 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.049s	user 0.021s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23123,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.451668 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:02.471768 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.020s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6224,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.472479 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:02.602310 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.130s	user 0.093s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":855,"lbm_read_time_us":7560,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25564,"lbm_writes_lt_1ms":443,"mutex_wait_us":343,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2000}
I20260812 06:19:02.603277 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=11.118625
I20260812 06:19:02.644433 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.041s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17548,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:02.645030 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:02.672120 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5494,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.672621 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:02.684576 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.685074 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:02.839859 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.155s	user 0.101s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":331,"lbm_read_time_us":10801,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31577,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:19:02.840662 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=11.118625
I20260812 06:19:02.875625 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.035s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14915,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:02.876240 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:02.886612 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.887200 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:02.918263 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushMRSOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234476,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1198,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1407,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:02.918972 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): free 120553595 bytes of WAL
I20260812 06:19:02.919265 27551 log_reader.cc:385] T 6c3f2b1055cd474e9c9aa2ae807bfbd3: removed 12 log segments from log reader
I20260812 06:19:02.919344 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000025 (ops 120-124)
I20260812 06:19:02.919404 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000026 (ops 125-129)
I20260812 06:19:02.919476 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000027 (ops 130-134)
I20260812 06:19:02.919523 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000028 (ops 135-139)
I20260812 06:19:02.919562 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000029 (ops 140-144)
I20260812 06:19:02.919600 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000030 (ops 145-148)
I20260812 06:19:02.919639 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000031 (ops 149-153)
I20260812 06:19:02.919674 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000032 (ops 154-158)
I20260812 06:19:02.919700 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000033 (ops 159-163)
I20260812 06:19:02.919734 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000034 (ops 164-168)
I20260812 06:19:02.919775 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000035 (ops 169-172)
I20260812 06:19:02.919821 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000036 (ops 173-177)
I20260812 06:19:02.950722 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:02.951289 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=3.181125
I20260812 06:19:02.971242 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7579,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:02.971747 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): free 12018006 bytes of WAL
I20260812 06:19:02.971992 27551 log_reader.cc:385] T 6c3f2b1055cd474e9c9aa2ae807bfbd3: removed 1 log segments from log reader
I20260812 06:19:02.972051 27551 log.cc:1079] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/6c3f2b1055cd474e9c9aa2ae807bfbd3/wal-000000037 (ops 178-182)
I20260812 06:19:02.975200 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: LogGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:02.975524 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): 472 bytes on disk
I20260812 06:19:02.975991 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: UndoDeltaBlockGCOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.976539 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:02.989609 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5169,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.989972 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:03.176342 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.186s	user 0.138s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836354,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1241,"lbm_read_time_us":13256,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36380,"lbm_writes_lt_1ms":643,"mutex_wait_us":380,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:03.177223 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=14.095187
I20260812 06:19:03.230381 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.053s	user 0.044s	sys 0.005s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21974,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.230880 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=2.188937
I20260812 06:19:03.243887 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.013s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.244539 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=1.000000
I20260812 06:19:03.421727 27385 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.179s	user 1.982s	sys 0.173s
I20260812 06:19:03.423787 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: MajorDeltaCompactionOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.179s	user 0.140s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":11709,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36317,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":60416,"update_count":2500}
I20260812 06:19:03.424474 27665 maintenance_manager.cc:419] P d45eaef304f24800bea8337dcd8f4998: Scheduling FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3): perf score=14.095187
I20260812 06:19:03.453408 27385 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.031s	user 0.003s	sys 0.000s
I20260812 06:19:03.454090 27385 tablet_server.cc:179] TabletServer@127.26.190.65:0 shutting down...
I20260812 06:19:03.469005 27551 maintenance_manager.cc:643] P d45eaef304f24800bea8337dcd8f4998: FlushDeltaMemStoresOp(6c3f2b1055cd474e9c9aa2ae807bfbd3) complete. Timing: real 0.044s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19884,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.469578 27385 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:03.470021 27385 tablet_replica.cc:333] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998: stopping tablet replica
I20260812 06:19:03.470264 27385 raft_consensus.cc:2243] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:03.470496 27385 raft_consensus.cc:2272] T 6c3f2b1055cd474e9c9aa2ae807bfbd3 P d45eaef304f24800bea8337dcd8f4998 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:03.485342 27385 tablet_server.cc:196] TabletServer@127.26.190.65:0 shutdown complete.
I20260812 06:19:03.490214 27385 master.cc:562] Master@127.26.190.126:39691 shutting down...
I20260812 06:19:03.493636 27385 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:03.493772 27385 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:03.493831 27385 tablet_replica.cc:333] T 00000000000000000000000000000000 P a4ee33acbbd04891a6cde536fa8d5ac7: stopping tablet replica
I20260812 06:19:03.505988 27385 master.cc:584] Master@127.26.190.126:39691 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5619 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:03.601369 27385 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.190.126:38019
I20260812 06:19:03.601713 27385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:03.604125 27385 server_base.cc:1061] running on GCE node
W20260812 06:19:03.604192 27729 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:03.604192 27728 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.604213 27732 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:03.604540 27385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.604589 27385 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:03.604605 27385 hybrid_clock.cc:648] HybridClock initialized: now 1786515543604605 us; error 0 us; skew 500 ppm
I20260812 06:19:03.605504 27385 webserver.cc:533] Webserver started at http://127.26.190.126:44661/ using document root <none> and password file <none>
I20260812 06:19:03.605719 27385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.605769 27385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.605871 27385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.606281 27385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/master-0-root/instance:
uuid: "b64b382142624639b5cc8755afd72b5e"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-g170"
I20260812 06:19:03.607812 27385 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:03.609059 27738 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:03.609347 27385 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:03.609434 27385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/master-0-root
uuid: "b64b382142624639b5cc8755afd72b5e"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-g170"
I20260812 06:19:03.609501 27385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-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:03.618324 27385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.618690 27385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.623090 27385 rpc_server.cc:307] RPC server started. Bound to: 127.26.190.126:38019
I20260812 06:19:03.625541 27821 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.190.126:38019 every 8 connection(s)
I20260812 06:19:03.641052 27822 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:03.642875 27822 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e: Bootstrap starting.
I20260812 06:19:03.643587 27822 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.644608 27822 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e: No bootstrap required, opened a new log
I20260812 06:19:03.645002 27822 raft_consensus.cc:359] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b64b382142624639b5cc8755afd72b5e" member_type: VOTER }
I20260812 06:19:03.645087 27822 raft_consensus.cc:385] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.645109 27822 raft_consensus.cc:740] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b64b382142624639b5cc8755afd72b5e, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.645269 27822 consensus_queue.cc:260] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [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: "b64b382142624639b5cc8755afd72b5e" member_type: VOTER }
I20260812 06:19:03.645366 27822 raft_consensus.cc:399] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.645412 27822 raft_consensus.cc:493] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.645443 27822 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.646056 27822 raft_consensus.cc:515] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b64b382142624639b5cc8755afd72b5e" member_type: VOTER }
I20260812 06:19:03.646162 27822 leader_election.cc:304] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [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: b64b382142624639b5cc8755afd72b5e; no voters: 
I20260812 06:19:03.646325 27822 leader_election.cc:290] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.646479 27833 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.646673 27833 raft_consensus.cc:697] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 1 LEADER]: Becoming Leader. State: Replica: b64b382142624639b5cc8755afd72b5e, State: Running, Role: LEADER
I20260812 06:19:03.646812 27822 sys_catalog.cc:565] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:03.646842 27833 consensus_queue.cc:237] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [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: "b64b382142624639b5cc8755afd72b5e" member_type: VOTER }
I20260812 06:19:03.647267 27834 sys_catalog.cc:455] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b64b382142624639b5cc8755afd72b5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b64b382142624639b5cc8755afd72b5e" member_type: VOTER } }
I20260812 06:19:03.647303 27835 sys_catalog.cc:455] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [sys.catalog]: SysCatalogTable state changed. Reason: New leader b64b382142624639b5cc8755afd72b5e. Latest consensus state: current_term: 1 leader_uuid: "b64b382142624639b5cc8755afd72b5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b64b382142624639b5cc8755afd72b5e" member_type: VOTER } }
I20260812 06:19:03.647419 27835 sys_catalog.cc:458] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.647712 27842 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:03.647991 27834 sys_catalog.cc:458] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.648504 27842 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:03.648826 27385 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:03.650357 27842 catalog_manager.cc:1383] Generated new cluster ID: bb6590ba642b4cb3a7325e1a66cfc801
I20260812 06:19:03.650415 27842 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:03.681582 27842 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:03.682132 27842 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:03.693324 27842 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e: Generated new TSK 0
I20260812 06:19:03.693533 27842 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:03.713374 27385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:03.715528 27863 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:03.715646 27862 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:03.715802 27385 server_base.cc:1061] running on GCE node
W20260812 06:19:03.715649 27865 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:03.716032 27385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.716094 27385 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:03.716117 27385 hybrid_clock.cc:648] HybridClock initialized: now 1786515543716117 us; error 0 us; skew 500 ppm
I20260812 06:19:03.717226 27385 webserver.cc:533] Webserver started at http://127.26.190.65:44127/ using document root <none> and password file <none>
I20260812 06:19:03.717408 27385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.717480 27385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.717567 27385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.718014 27385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/instance:
uuid: "5e4694d8f806477c988cf64f47acec06"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-g170"
I20260812 06:19:03.719610 27385 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:03.720753 27873 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:03.721107 27385 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:03.721205 27385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root
uuid: "5e4694d8f806477c988cf64f47acec06"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-g170"
I20260812 06:19:03.721297 27385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-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:03.741919 27385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.742372 27385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.742763 27385 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:03.743278 27385 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:03.743340 27385 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.743399 27385 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:03.743450 27385 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.747963 27385 rpc_server.cc:307] RPC server started. Bound to: 127.26.190.65:41961
I20260812 06:19:03.748025 27985 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.190.65:41961 every 8 connection(s)
I20260812 06:19:03.767108 27986 heartbeater.cc:344] Connected to a master server at 127.26.190.126:38019
I20260812 06:19:03.767287 27986 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:03.767596 27986 heartbeater.cc:507] Master 127.26.190.126:38019 requested a full tablet report, sending...
I20260812 06:19:03.768476 27764 ts_manager.cc:194] Registered new tserver with Master: 5e4694d8f806477c988cf64f47acec06 (127.26.190.65:41961)
I20260812 06:19:03.768527 27385 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020100762s
I20260812 06:19:03.769439 27764 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38222
I20260812 06:19:03.777056 27764 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38226:
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:03.786746 27922 tablet_service.cc:1511] Processing CreateTablet for tablet ec9b8b74b1484ff2946a3208ff8d977c (DEFAULT_TABLE table=heavy-update-compaction-test [id=c6003c9e6aa44883986b38d1ac2e5fab]), partition=
I20260812 06:19:03.787056 27922 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ec9b8b74b1484ff2946a3208ff8d977c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:03.789039 28006 tablet_bootstrap.cc:492] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Bootstrap starting.
I20260812 06:19:03.789906 28006 tablet_bootstrap.cc:654] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.790977 28006 tablet_bootstrap.cc:492] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: No bootstrap required, opened a new log
I20260812 06:19:03.791056 28006 ts_tablet_manager.cc:1403] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:03.791422 28006 raft_consensus.cc:359] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e4694d8f806477c988cf64f47acec06" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 41961 } }
I20260812 06:19:03.791509 28006 raft_consensus.cc:385] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.791531 28006 raft_consensus.cc:740] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5e4694d8f806477c988cf64f47acec06, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.791666 28006 consensus_queue.cc:260] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [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: "5e4694d8f806477c988cf64f47acec06" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 41961 } }
I20260812 06:19:03.791754 28006 raft_consensus.cc:399] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.791777 28006 raft_consensus.cc:493] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.791832 28006 raft_consensus.cc:3060] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.792598 28006 raft_consensus.cc:515] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e4694d8f806477c988cf64f47acec06" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 41961 } }
I20260812 06:19:03.792757 28006 leader_election.cc:304] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [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: 5e4694d8f806477c988cf64f47acec06; no voters: 
I20260812 06:19:03.793032 28006 leader_election.cc:290] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.793187 28010 raft_consensus.cc:2804] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.793362 28006 ts_tablet_manager.cc:1434] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:03.793407 27986 heartbeater.cc:499] Master 127.26.190.126:38019 was elected leader, sending a full tablet report...
I20260812 06:19:03.793423 28010 raft_consensus.cc:697] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 1 LEADER]: Becoming Leader. State: Replica: 5e4694d8f806477c988cf64f47acec06, State: Running, Role: LEADER
I20260812 06:19:03.793572 28010 consensus_queue.cc:237] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [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: "5e4694d8f806477c988cf64f47acec06" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 41961 } }
I20260812 06:19:03.794895 27764 catalog_manager.cc:5719] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5e4694d8f806477c988cf64f47acec06 (127.26.190.65). New cstate: current_term: 1 leader_uuid: "5e4694d8f806477c988cf64f47acec06" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e4694d8f806477c988cf64f47acec06" member_type: VOTER last_known_addr { host: "127.26.190.65" port: 41961 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:03.858515 27385 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.013s	sys 0.011s
I20260812 06:19:03.998919 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=19.054940
I20260812 06:19:04.168524 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.169s	user 0.137s	sys 0.020s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":804,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42850,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:04.169312 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c): free 20743831 bytes of WAL
I20260812 06:19:04.169632 27880 log_reader.cc:385] T ec9b8b74b1484ff2946a3208ff8d977c: removed 2 log segments from log reader
I20260812 06:19:04.169690 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000001 (ops 1-6)
I20260812 06:19:04.169770 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000002 (ops 7-11)
I20260812 06:19:04.174124 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:04.174541 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c): 16411392 bytes on disk
I20260812 06:19:04.174998 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c) 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:04.175400 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:04.196043 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.020s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.196610 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:04.358508 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.162s	user 0.090s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":682,"lbm_read_time_us":11219,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26921,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":365,"threads_started":5,"update_count":2000}
I20260812 06:19:04.359193 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:04.422556 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.063s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22954,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.423071 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:04.438791 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.439321 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:04.629948 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.190s	user 0.110s	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":676,"lbm_read_time_us":14010,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30258,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:19:04.630586 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:04.680593 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.050s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.681057 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:04.846820 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.166s	user 0.119s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":352,"lbm_read_time_us":12466,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27219,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":102400,"update_count":2000}
I20260812 06:19:04.847450 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=10.126437
I20260812 06:19:04.881901 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.034s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14951,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.882421 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:04.896090 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.896529 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:05.020627 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.124s	user 0.079s	sys 0.044s 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":1066,"lbm_read_time_us":9359,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24215,"lbm_writes_lt_1ms":443,"mutex_wait_us":304,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27008,"update_count":2000}
I20260812 06:19:05.021363 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=10.126437
I20260812 06:19:05.071270 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.050s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17069,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.071764 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:05.082412 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.082873 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:05.211994 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.129s	user 0.099s	sys 0.027s 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":190,"lbm_read_time_us":10449,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25136,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:19:05.212589 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=10.126437
I20260812 06:19:05.260300 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.047s	user 0.029s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22362,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.261047 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:05.272832 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4289,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.273424 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:05.407832 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.134s	user 0.118s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":407,"lbm_read_time_us":9746,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26320,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:19:05.408610 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=10.126437
I20260812 06:19:05.463881 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.055s	user 0.020s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16019,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.464402 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:05.475381 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.475845 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:05.518627 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.043s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1658,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:05.519219 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c): free 112239306 bytes of WAL
I20260812 06:19:05.519443 27880 log_reader.cc:385] T ec9b8b74b1484ff2946a3208ff8d977c: removed 11 log segments from log reader
I20260812 06:19:05.519491 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000003 (ops 12-16)
I20260812 06:19:05.519519 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000004 (ops 17-20)
I20260812 06:19:05.519578 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000005 (ops 21-25)
I20260812 06:19:05.519613 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000006 (ops 26-30)
I20260812 06:19:05.519650 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000007 (ops 31-35)
I20260812 06:19:05.519683 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000008 (ops 36-40)
I20260812 06:19:05.519719 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000009 (ops 41-45)
I20260812 06:19:05.519758 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000010 (ops 46-50)
I20260812 06:19:05.519797 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000011 (ops 51-55)
I20260812 06:19:05.519834 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000012 (ops 56-60)
I20260812 06:19:05.519872 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000013 (ops 61-65)
I20260812 06:19:05.544548 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:05.545051 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:05.564563 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.019s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.565186 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:05.575774 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.576361 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:05.799029 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.222s	user 0.143s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877336,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":636,"lbm_read_time_us":15696,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38291,"lbm_writes_lt_1ms":643,"mutex_wait_us":87,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:19:05.800406 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c): 462 bytes on disk
I20260812 06:19:05.801123 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":126,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.801842 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=16.079562
I20260812 06:19:05.853817 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.052s	user 0.029s	sys 0.020s Metrics: {"bytes_written":18091888,"delete_count":0,"lbm_write_time_us":22244,"lbm_writes_lt_1ms":444,"reinsert_count":0,"update_count":2205}
I20260812 06:19:05.854282 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.196750
I20260812 06:19:05.865077 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.011s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2830884,"delete_count":0,"lbm_write_time_us":2818,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:05.865505 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:05.875452 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3801,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.875859 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:06.082944 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.207s	user 0.139s	sys 0.067s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877177,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":591,"lbm_read_time_us":15347,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32604,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":3000}
I20260812 06:19:06.083590 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:06.130211 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.046s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21932,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.130846 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:06.152262 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.152858 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:06.163139 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.163555 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:06.385025 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.221s	user 0.162s	sys 0.055s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877222,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3689,"lbm_read_time_us":15188,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37458,"lbm_writes_lt_1ms":643,"mutex_wait_us":3234,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3000}
I20260812 06:19:06.385730 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:06.447395 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.061s	user 0.023s	sys 0.025s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22318,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.448047 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:06.462523 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5750,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.463043 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:06.666738 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.203s	user 0.160s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":87,"lbm_read_time_us":15001,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35274,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:19:06.667550 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:06.722633 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.055s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24951,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.723178 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:06.735947 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.736546 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:06.920995 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.184s	user 0.109s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2872,"lbm_read_time_us":13639,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28071,"lbm_writes_lt_1ms":543,"mutex_wait_us":2515,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:06.921833 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:06.994091 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.072s	user 0.039s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27625,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.994808 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:07.018914 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.024s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.019551 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:07.064332 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.045s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1389,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1877,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:07.065145 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=3.181125
I20260812 06:19:07.080590 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.015s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5241,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:07.081081 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c): free 133024374 bytes of WAL
I20260812 06:19:07.081362 27880 log_reader.cc:385] T ec9b8b74b1484ff2946a3208ff8d977c: removed 13 log segments from log reader
I20260812 06:19:07.081444 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000014 (ops 66-70)
I20260812 06:19:07.081501 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000015 (ops 71-74)
I20260812 06:19:07.081568 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000016 (ops 75-79)
I20260812 06:19:07.081615 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000017 (ops 80-84)
I20260812 06:19:07.081708 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000018 (ops 85-89)
I20260812 06:19:07.081773 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000019 (ops 90-94)
I20260812 06:19:07.081822 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000020 (ops 95-99)
I20260812 06:19:07.081859 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000021 (ops 100-104)
I20260812 06:19:07.081898 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000022 (ops 105-109)
I20260812 06:19:07.081938 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000023 (ops 110-114)
I20260812 06:19:07.081982 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000024 (ops 115-119)
I20260812 06:19:07.082024 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000025 (ops 120-124)
I20260812 06:19:07.082075 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000026 (ops 125-129)
I20260812 06:19:07.116182 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:07.116681 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:07.129670 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4224,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.130167 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c): 471 bytes on disk
I20260812 06:19:07.130630 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.131270 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:07.141054 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3608,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.141629 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:07.407461 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.266s	user 0.177s	sys 0.088s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1121,"lbm_read_time_us":17977,"lbm_reads_lt_1ms":875,"lbm_write_time_us":50509,"lbm_writes_lt_1ms":843,"mutex_wait_us":322,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":73,"threads_started":1,"update_count":4000}
I20260812 06:19:07.408087 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=18.063937
I20260812 06:19:07.476238 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.068s	user 0.033s	sys 0.030s Metrics: {"bytes_written":20512311,"delete_count":0,"lbm_write_time_us":28875,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:07.477181 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=3.181125
I20260812 06:19:07.503166 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.026s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4348804,"delete_count":0,"lbm_write_time_us":6639,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:19:07.503664 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:07.513913 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:19:07.514357 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:07.706627 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.192s	user 0.156s	sys 0.035s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979624,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1492,"lbm_read_time_us":15390,"lbm_reads_lt_1ms":773,"lbm_write_time_us":40211,"lbm_writes_lt_1ms":743,"mutex_wait_us":43,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":3500}
I20260812 06:19:07.707435 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:07.755364 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.047s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20746,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.756120 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:07.772738 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.773432 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:07.941956 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.168s	user 0.128s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":831,"lbm_read_time_us":12346,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32553,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:07.942699 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:08.002146 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.059s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23572,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.002635 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:08.013609 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.014211 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:08.205008 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.190s	user 0.136s	sys 0.051s 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":673,"lbm_read_time_us":12923,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30530,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:08.205852 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=14.095187
I20260812 06:19:08.270761 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.065s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25741,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.271430 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:08.286948 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.287509 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:08.467468 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.180s	user 0.118s	sys 0.060s 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":1104,"lbm_read_time_us":13429,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31542,"lbm_writes_lt_1ms":543,"mutex_wait_us":363,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:08.468143 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=11.118625
I20260812 06:19:08.514158 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.046s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15723,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.514729 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:08.526346 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.526942 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:08.563900 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushMRSOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.037s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1480,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1896,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:08.564746 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c): free 116396487 bytes of WAL
I20260812 06:19:08.565069 27880 log_reader.cc:385] T ec9b8b74b1484ff2946a3208ff8d977c: removed 11 log segments from log reader
I20260812 06:19:08.565114 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000027 (ops 130-134)
I20260812 06:19:08.565145 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000028 (ops 135-139)
I20260812 06:19:08.565201 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000029 (ops 140-145)
I20260812 06:19:08.565253 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000030 (ops 146-150)
I20260812 06:19:08.565287 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000031 (ops 151-155)
I20260812 06:19:08.565312 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000032 (ops 156-160)
I20260812 06:19:08.565351 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000033 (ops 161-165)
I20260812 06:19:08.565389 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000034 (ops 166-170)
I20260812 06:19:08.565428 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000035 (ops 171-175)
I20260812 06:19:08.565464 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000036 (ops 176-180)
I20260812 06:19:08.565505 27880 log.cc:1079] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: Deleting log segment in path: /tmp/dist-test-taskUB1ptk/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537971572-27385-0/minicluster-data/ts-0-root/wals/ec9b8b74b1484ff2946a3208ff8d977c/wal-000000037 (ops 181-185)
I20260812 06:19:08.592305 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: LogGCOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:08.592724 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c): 447 bytes on disk
I20260812 06:19:08.593230 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: UndoDeltaBlockGCOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:08.593777 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:08.617049 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.023s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.617501 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=2.188937
I20260812 06:19:08.627894 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.628288 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:08.835005 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.207s	user 0.116s	sys 0.088s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3279,"lbm_read_time_us":13894,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33784,"lbm_writes_lt_1ms":643,"mutex_wait_us":2427,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":109,"threads_started":1,"update_count":3000}
I20260812 06:19:08.835868 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=15.087375
I20260812 06:19:08.902783 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.067s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":28455,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:08.903309 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=6.157687
I20260812 06:19:08.923478 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: FlushDeltaMemStoresOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8361,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:08.923944 27989 maintenance_manager.cc:419] P 5e4694d8f806477c988cf64f47acec06: Scheduling MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c): perf score=1.000000
I20260812 06:19:08.944550 27385 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.086s	user 1.979s	sys 0.180s
I20260812 06:19:09.011557 27385 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.001s	sys 0.000s
I20260812 06:19:09.012071 27385 tablet_server.cc:179] TabletServer@127.26.190.65:0 shutting down...
I20260812 06:19:09.090605 27880 maintenance_manager.cc:643] P 5e4694d8f806477c988cf64f47acec06: MajorDeltaCompactionOp(ec9b8b74b1484ff2946a3208ff8d977c) complete. Timing: real 0.166s	user 0.106s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":14110,"lbm_reads_lt_1ms":668,"lbm_write_time_us":31556,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":3000}
I20260812 06:19:09.091315 27385 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:09.091600 27385 tablet_replica.cc:333] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06: stopping tablet replica
I20260812 06:19:09.091718 27385 raft_consensus.cc:2243] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:09.091943 27385 raft_consensus.cc:2272] T ec9b8b74b1484ff2946a3208ff8d977c P 5e4694d8f806477c988cf64f47acec06 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:09.112110 27385 tablet_server.cc:196] TabletServer@127.26.190.65:0 shutdown complete.
I20260812 06:19:09.145618 27385 master.cc:562] Master@127.26.190.126:38019 shutting down...
I20260812 06:19:09.149938 27385 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:09.150136 27385 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:09.150189 27385 tablet_replica.cc:333] T 00000000000000000000000000000000 P b64b382142624639b5cc8755afd72b5e: stopping tablet replica
I20260812 06:19:09.162608 27385 master.cc:584] Master@127.26.190.126:38019 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5653 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11273 ms total)

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