[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:50.124766 14736 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.100.62:38827
I20260812 06:19:50.125671 14736 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:50.126210 14736 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:50.131969 14736 server_base.cc:1061] running on GCE node
W20260812 06:19:50.131976 14745 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:50.131989 14747 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:50.132081 14742 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:50.132575 14736 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:50.132664 14736 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:50.132705 14736 hybrid_clock.cc:648] HybridClock initialized: now 1786515590132703 us; error 0 us; skew 500 ppm
I20260812 06:19:50.134222 14736 webserver.cc:533] Webserver started at http://127.14.100.62:40849/ using document root <none> and password file <none>
I20260812 06:19:50.134683 14736 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:50.134744 14736 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:50.134961 14736 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:50.136438 14736 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/master-0-root/instance:
uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b"
format_stamp: "Formatted at 2026-08-12 06:19:50 on dist-test-slave-bndk"
I20260812 06:19:50.139546 14736 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.002s
I20260812 06:19:50.141306 14759 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:50.142149 14736 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:19:50.142247 14736 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/master-0-root
uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b"
format_stamp: "Formatted at 2026-08-12 06:19:50 on dist-test-slave-bndk"
I20260812 06:19:50.142326 14736 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-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:50.165458 14736 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:50.165949 14736 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:50.166086 14736 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:50.172601 14736 rpc_server.cc:307] RPC server started. Bound to: 127.14.100.62:38827
I20260812 06:19:50.172645 14834 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.100.62:38827 every 8 connection(s)
I20260812 06:19:50.174541 14836 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:50.179438 14836 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b: Bootstrap starting.
I20260812 06:19:50.181589 14836 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:50.182372 14836 log.cc:826] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:50.183759 14836 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b: No bootstrap required, opened a new log
I20260812 06:19:50.186280 14836 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b" member_type: VOTER }
I20260812 06:19:50.186425 14836 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:50.186488 14836 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6dc2d5eced5a42d4ae3e4c550cb1554b, State: Initialized, Role: FOLLOWER
I20260812 06:19:50.186991 14836 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [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: "6dc2d5eced5a42d4ae3e4c550cb1554b" member_type: VOTER }
I20260812 06:19:50.187139 14836 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:50.187199 14836 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:50.187311 14836 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:50.187978 14836 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b" member_type: VOTER }
I20260812 06:19:50.188349 14836 leader_election.cc:304] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [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: 6dc2d5eced5a42d4ae3e4c550cb1554b; no voters: 
I20260812 06:19:50.188602 14836 leader_election.cc:290] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:50.188715 14840 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:50.188906 14840 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 1 LEADER]: Becoming Leader. State: Replica: 6dc2d5eced5a42d4ae3e4c550cb1554b, State: Running, Role: LEADER
I20260812 06:19:50.189317 14840 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [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: "6dc2d5eced5a42d4ae3e4c550cb1554b" member_type: VOTER }
I20260812 06:19:50.189459 14836 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:50.190992 14842 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b" member_type: VOTER } }
I20260812 06:19:50.190984 14843 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6dc2d5eced5a42d4ae3e4c550cb1554b. Latest consensus state: current_term: 1 leader_uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc2d5eced5a42d4ae3e4c550cb1554b" member_type: VOTER } }
I20260812 06:19:50.191112 14843 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:50.191110 14842 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:50.191545 14736 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:50.192107 14858 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:50.194006 14858 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:50.198438 14858 catalog_manager.cc:1383] Generated new cluster ID: 4a56ffc2266a4e7494c62d23766f370d
I20260812 06:19:50.198491 14858 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:50.209909 14858 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:50.210631 14858 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:50.217475 14858 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b: Generated new TSK 0
I20260812 06:19:50.217985 14858 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:50.224511 14736 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:50.227248 14871 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:50.227336 14870 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:50.227371 14736 server_base.cc:1061] running on GCE node
W20260812 06:19:50.227469 14876 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:50.227723 14736 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:50.227777 14736 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:50.227795 14736 hybrid_clock.cc:648] HybridClock initialized: now 1786515590227795 us; error 0 us; skew 500 ppm
I20260812 06:19:50.228652 14736 webserver.cc:533] Webserver started at http://127.14.100.1:38453/ using document root <none> and password file <none>
I20260812 06:19:50.228806 14736 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:50.228937 14736 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:50.229022 14736 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:50.229440 14736 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/instance:
uuid: "3c4fa9b7d0784e1ea7366dc353999dce"
format_stamp: "Formatted at 2026-08-12 06:19:50 on dist-test-slave-bndk"
I20260812 06:19:50.231122 14736 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:50.232162 14886 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:50.232411 14736 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:50.232493 14736 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root
uuid: "3c4fa9b7d0784e1ea7366dc353999dce"
format_stamp: "Formatted at 2026-08-12 06:19:50 on dist-test-slave-bndk"
I20260812 06:19:50.232555 14736 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-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:50.243274 14736 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:50.243697 14736 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:50.244167 14736 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:50.245115 14736 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:50.245178 14736 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:50.245293 14736 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:50.245343 14736 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:50.251966 14736 rpc_server.cc:307] RPC server started. Bound to: 127.14.100.1:38781
I20260812 06:19:50.252007 14995 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.100.1:38781 every 8 connection(s)
I20260812 06:19:50.260946 14996 heartbeater.cc:344] Connected to a master server at 127.14.100.62:38827
I20260812 06:19:50.261157 14996 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:50.261574 14996 heartbeater.cc:507] Master 127.14.100.62:38827 requested a full tablet report, sending...
I20260812 06:19:50.262841 14784 ts_manager.cc:194] Registered new tserver with Master: 3c4fa9b7d0784e1ea7366dc353999dce (127.14.100.1:38781)
I20260812 06:19:50.263716 14736 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01111828s
I20260812 06:19:50.264008 14784 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44112
I20260812 06:19:50.272886 14784 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44118:
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:50.286206 14936 tablet_service.cc:1511] Processing CreateTablet for tablet 66602eeecfe144939a74456070c0f1ff (DEFAULT_TABLE table=heavy-update-compaction-test [id=48b0cc0dc62d4f67a7b45d0db701e0e9]), partition=
I20260812 06:19:50.286665 14936 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 66602eeecfe144939a74456070c0f1ff. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:50.289274 15016 tablet_bootstrap.cc:492] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Bootstrap starting.
I20260812 06:19:50.290186 15016 tablet_bootstrap.cc:654] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:50.291280 15016 tablet_bootstrap.cc:492] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: No bootstrap required, opened a new log
I20260812 06:19:50.291381 15016 ts_tablet_manager.cc:1403] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:50.291793 15016 raft_consensus.cc:359] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c4fa9b7d0784e1ea7366dc353999dce" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 38781 } }
I20260812 06:19:50.291885 15016 raft_consensus.cc:385] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:50.291917 15016 raft_consensus.cc:740] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3c4fa9b7d0784e1ea7366dc353999dce, State: Initialized, Role: FOLLOWER
I20260812 06:19:50.292044 15016 consensus_queue.cc:260] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [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: "3c4fa9b7d0784e1ea7366dc353999dce" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 38781 } }
I20260812 06:19:50.292121 15016 raft_consensus.cc:399] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:50.292164 15016 raft_consensus.cc:493] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:50.292210 15016 raft_consensus.cc:3060] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:50.292896 15016 raft_consensus.cc:515] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c4fa9b7d0784e1ea7366dc353999dce" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 38781 } }
I20260812 06:19:50.293018 15016 leader_election.cc:304] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [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: 3c4fa9b7d0784e1ea7366dc353999dce; no voters: 
I20260812 06:19:50.293188 15016 leader_election.cc:290] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:50.293350 15018 raft_consensus.cc:2804] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:50.293542 15016 ts_tablet_manager.cc:1434] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:50.293610 15018 raft_consensus.cc:697] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 1 LEADER]: Becoming Leader. State: Replica: 3c4fa9b7d0784e1ea7366dc353999dce, State: Running, Role: LEADER
I20260812 06:19:50.293960 14996 heartbeater.cc:499] Master 127.14.100.62:38827 was elected leader, sending a full tablet report...
I20260812 06:19:50.294409 15018 consensus_queue.cc:237] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [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: "3c4fa9b7d0784e1ea7366dc353999dce" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 38781 } }
I20260812 06:19:50.296705 14784 catalog_manager.cc:5719] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce reported cstate change: term changed from 0 to 1, leader changed from <none> to 3c4fa9b7d0784e1ea7366dc353999dce (127.14.100.1). New cstate: current_term: 1 leader_uuid: "3c4fa9b7d0784e1ea7366dc353999dce" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c4fa9b7d0784e1ea7366dc353999dce" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 38781 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:50.353742 14736 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.016s	sys 0.008s
I20260812 06:19:50.502998 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushMRSOp(66602eeecfe144939a74456070c0f1ff): perf score=23.023690
I20260812 06:19:50.650714 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushMRSOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.147s	user 0.104s	sys 0.041s Metrics: {"bytes_written":9640924,"cfile_init":1,"compiler_manager_pool.queue_time_us":209,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":840,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38347,"lbm_writes_lt_1ms":792,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":183552,"thread_start_us":123,"threads_started":1,"update_count":1175}
I20260812 06:19:50.652258 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling LogGCOp(66602eeecfe144939a74456070c0f1ff): free 20743880 bytes of WAL
I20260812 06:19:50.652673 14896 log_reader.cc:385] T 66602eeecfe144939a74456070c0f1ff: removed 2 log segments from log reader
I20260812 06:19:50.652802 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000001 (ops 1-6)
I20260812 06:19:50.652905 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000002 (ops 7-11)
I20260812 06:19:50.658649 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: LogGCOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:50.659152 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=1.196750
I20260812 06:19:50.681160 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.022s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":4432,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:19:50.681583 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:50.696162 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3138,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.696547 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff): 20513818 bytes on disk
I20260812 06:19:50.697104 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:19:50.697516 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:50.852209 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.155s	user 0.112s	sys 0.035s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20713358,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":401,"lbm_read_time_us":10862,"lbm_reads_lt_1ms":469,"lbm_write_time_us":23877,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":314,"threads_started":5,"update_count":2000}
I20260812 06:19:50.852674 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:50.898944 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.046s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.899381 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:50.908857 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.909284 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:51.025570 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.116s	user 0.103s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":6840,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23370,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:51.026057 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:51.064919 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.039s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15931,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.065483 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:51.080134 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.080564 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:51.196827 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.116s	user 0.100s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":7608,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23047,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:51.197383 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:51.245919 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.048s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13440,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.246425 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:51.261341 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.261746 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:51.397009 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.135s	user 0.075s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":881,"lbm_read_time_us":10922,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20681,"lbm_writes_lt_1ms":443,"mutex_wait_us":225,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:19:51.397562 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:51.441330 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.044s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15280,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.441730 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:51.451313 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.451727 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:51.573850 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.122s	user 0.106s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":692,"lbm_read_time_us":9401,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22637,"lbm_writes_lt_1ms":443,"mutex_wait_us":287,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:51.574314 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:51.615619 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.041s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13895,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.616017 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:51.625569 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.626032 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:51.753312 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.127s	user 0.105s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1177,"lbm_read_time_us":7925,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25241,"lbm_writes_lt_1ms":443,"mutex_wait_us":831,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.754446 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:51.799508 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.045s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16511,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.799944 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:51.809664 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.810111 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushMRSOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:51.849121 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushMRSOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.039s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1152,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1309,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:51.849958 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling LogGCOp(66602eeecfe144939a74456070c0f1ff): free 112239307 bytes of WAL
I20260812 06:19:51.850193 14896 log_reader.cc:385] T 66602eeecfe144939a74456070c0f1ff: removed 11 log segments from log reader
I20260812 06:19:51.850255 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000003 (ops 12-16)
I20260812 06:19:51.850301 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000004 (ops 17-21)
I20260812 06:19:51.850329 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000005 (ops 22-26)
I20260812 06:19:51.850353 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000006 (ops 27-30)
I20260812 06:19:51.850383 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000007 (ops 31-35)
I20260812 06:19:51.850414 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000008 (ops 36-40)
I20260812 06:19:51.850443 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000009 (ops 41-45)
I20260812 06:19:51.850467 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000010 (ops 46-50)
I20260812 06:19:51.850492 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000011 (ops 51-55)
I20260812 06:19:51.850520 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000012 (ops 56-60)
I20260812 06:19:51.850549 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000013 (ops 61-65)
I20260812 06:19:51.875176 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: LogGCOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:51.875550 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=3.181125
I20260812 06:19:51.895150 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.019s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:51.895557 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff): 447 bytes on disk
I20260812 06:19:51.895910 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.896324 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:51.905025 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3200,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.905376 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:52.089448 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.184s	user 0.121s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":502,"lbm_read_time_us":12268,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29027,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":67,"threads_started":1,"update_count":3000}
I20260812 06:19:52.090288 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=14.095187
I20260812 06:19:52.131731 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.041s	user 0.017s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18173,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.133020 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:52.259837 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.127s	user 0.111s	sys 0.016s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":417,"lbm_read_time_us":8152,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22051,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:19:52.260327 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:52.290876 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.030s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12794,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.291352 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:52.302129 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.303036 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:52.426934 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.124s	user 0.089s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":857,"lbm_read_time_us":8581,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23071,"lbm_writes_lt_1ms":443,"mutex_wait_us":265,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:52.427423 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:52.465859 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.038s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16618,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.466336 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:52.476292 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.476835 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:52.600035 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.123s	user 0.101s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2633,"lbm_read_time_us":9095,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20522,"lbm_writes_lt_1ms":443,"mutex_wait_us":2361,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.600524 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:52.634241 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.034s	user 0.005s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12411,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.634708 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:52.644284 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.644680 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:52.771080 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.126s	user 0.114s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":332,"lbm_read_time_us":9820,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21980,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:52.771744 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:52.815841 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.044s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14505,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.816382 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:52.830631 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.831107 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:52.967960 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.137s	user 0.103s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":84,"lbm_read_time_us":10276,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20509,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":58752,"update_count":2000}
I20260812 06:19:52.968778 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:53.016947 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.048s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19301,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:53.017482 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:53.026758 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3432,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.027226 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:53.133708 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.106s	user 0.090s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":6965,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19813,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:53.134285 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:53.177151 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.043s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16439,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:53.177662 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:53.192119 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.192817 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushMRSOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:53.224426 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushMRSOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1213,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1965,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":2944}
I20260812 06:19:53.225152 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling LogGCOp(66602eeecfe144939a74456070c0f1ff): free 129320505 bytes of WAL
I20260812 06:19:53.225406 14896 log_reader.cc:385] T 66602eeecfe144939a74456070c0f1ff: removed 13 log segments from log reader
I20260812 06:19:53.225476 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000014 (ops 66-70)
I20260812 06:19:53.225512 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000015 (ops 71-75)
I20260812 06:19:53.225549 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000016 (ops 76-80)
I20260812 06:19:53.225582 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000017 (ops 81-84)
I20260812 06:19:53.225610 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000018 (ops 85-89)
I20260812 06:19:53.225636 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000019 (ops 90-94)
I20260812 06:19:53.225664 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000020 (ops 95-99)
I20260812 06:19:53.225696 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000021 (ops 100-104)
I20260812 06:19:53.225726 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000022 (ops 105-109)
I20260812 06:19:53.225754 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000023 (ops 110-114)
I20260812 06:19:53.225780 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000024 (ops 115-118)
I20260812 06:19:53.225809 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000025 (ops 119-123)
I20260812 06:19:53.225840 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000026 (ops 124-128)
I20260812 06:19:53.251037 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: LogGCOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:53.251403 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff): 473 bytes on disk
I20260812 06:19:53.251793 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff) 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:53.252276 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=3.181125
I20260812 06:19:53.263295 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4676998,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":117,"reinsert_count":0,"update_count":570}
I20260812 06:19:53.263716 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:53.272302 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.008s	user 0.003s	sys 0.003s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":3100,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:19:53.272857 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:53.436892 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.164s	user 0.121s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3649,"lbm_read_time_us":13204,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29936,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":65,"threads_started":1,"update_count":3000}
I20260812 06:19:53.437428 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=14.095187
I20260812 06:19:53.486992 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.049s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20237,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.487455 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:53.497895 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.498315 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:53.644264 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.146s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":8430,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27614,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":114560,"update_count":2500}
I20260812 06:19:53.644775 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=14.095187
I20260812 06:19:53.686120 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.041s	user 0.029s	sys 0.011s Metrics: {"bytes_written":16409887,"delete_count":0,"lbm_write_time_us":17895,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.686532 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:53.828621 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.142s	user 0.095s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713138,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":387,"lbm_read_time_us":9165,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24805,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:53.829123 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=11.118625
I20260812 06:19:53.865460 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.036s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14709,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:53.866024 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:53.886922 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.021s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3824,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.887382 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:53.897032 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.897526 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:54.071251 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.174s	user 0.113s	sys 0.054s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":194,"lbm_read_time_us":10551,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27805,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:19:54.071970 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=11.118625
I20260812 06:19:54.113646 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.041s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15362,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:54.114143 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:54.129356 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.015s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3892,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.129783 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:54.138473 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3231,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.138833 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:54.269734 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.131s	user 0.098s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":627,"lbm_read_time_us":9227,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25012,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:54.270283 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=11.118625
I20260812 06:19:54.299925 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.028s	user 0.021s	sys 0.004s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":12236,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:54.300720 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:54.314546 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.014s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4593,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.314976 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:54.427304 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.112s	user 0.076s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":817,"lbm_read_time_us":6529,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20804,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:54.427886 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=10.126437
I20260812 06:19:54.461017 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.033s	user 0.011s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12647,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:54.461484 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:54.470855 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.471379 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushMRSOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:54.502514 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushMRSOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.031s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1178,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1206,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:54.503189 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling LogGCOp(66602eeecfe144939a74456070c0f1ff): free 124257509 bytes of WAL
I20260812 06:19:54.503423 14896 log_reader.cc:385] T 66602eeecfe144939a74456070c0f1ff: removed 12 log segments from log reader
I20260812 06:19:54.503484 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000027 (ops 129-133)
I20260812 06:19:54.503525 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000028 (ops 134-138)
I20260812 06:19:54.503558 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000029 (ops 139-143)
I20260812 06:19:54.503589 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000030 (ops 144-148)
I20260812 06:19:54.503616 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000031 (ops 149-153)
I20260812 06:19:54.503640 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000032 (ops 154-158)
I20260812 06:19:54.503667 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000033 (ops 159-162)
I20260812 06:19:54.503697 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000034 (ops 163-167)
I20260812 06:19:54.503727 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000035 (ops 168-172)
I20260812 06:19:54.503752 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000036 (ops 173-177)
I20260812 06:19:54.503778 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000037 (ops 178-182)
I20260812 06:19:54.503803 14896 log.cc:1079] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/66602eeecfe144939a74456070c0f1ff/wal-000000038 (ops 183-187)
I20260812 06:19:54.529186 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: LogGCOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:54.529595 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=3.181125
I20260812 06:19:54.542145 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:54.542527 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:54.555449 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5171,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.555862 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff): 462 bytes on disk
I20260812 06:19:54.556239 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: UndoDeltaBlockGCOp(66602eeecfe144939a74456070c0f1ff) 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:19:54.556697 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:54.713460 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.157s	user 0.130s	sys 0.025s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":271,"lbm_read_time_us":11329,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29959,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:19:54.714002 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=14.095187
I20260812 06:19:54.761400 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.047s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19563,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.761889 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff): perf score=2.188937
I20260812 06:19:54.771718 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: FlushDeltaMemStoresOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.772130 14997 maintenance_manager.cc:419] P 3c4fa9b7d0784e1ea7366dc353999dce: Scheduling MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff): perf score=1.000000
I20260812 06:19:54.805944 14736 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.452s	user 1.646s	sys 0.129s
I20260812 06:19:54.854139 14736 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.048s	user 0.002s	sys 0.000s
I20260812 06:19:54.854759 14736 tablet_server.cc:179] TabletServer@127.14.100.1:0 shutting down...
I20260812 06:19:54.895388 14896 maintenance_manager.cc:643] P 3c4fa9b7d0784e1ea7366dc353999dce: MajorDeltaCompactionOp(66602eeecfe144939a74456070c0f1ff) complete. Timing: real 0.123s	user 0.087s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":11308,"lbm_reads_lt_1ms":568,"lbm_write_time_us":22313,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":89216,"update_count":2500}
I20260812 06:19:54.896037 14736 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:54.896422 14736 tablet_replica.cc:333] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce: stopping tablet replica
I20260812 06:19:54.896642 14736 raft_consensus.cc:2243] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:54.896858 14736 raft_consensus.cc:2272] T 66602eeecfe144939a74456070c0f1ff P 3c4fa9b7d0784e1ea7366dc353999dce [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:54.920204 14736 tablet_server.cc:196] TabletServer@127.14.100.1:0 shutdown complete.
I20260812 06:19:54.940804 14736 master.cc:562] Master@127.14.100.62:38827 shutting down...
I20260812 06:19:54.943979 14736 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:54.944123 14736 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:54.944173 14736 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6dc2d5eced5a42d4ae3e4c550cb1554b: stopping tablet replica
I20260812 06:19:54.956032 14736 master.cc:584] Master@127.14.100.62:38827 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4903 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:55.028098 14736 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.100.62:36883
I20260812 06:19:55.028450 14736 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:55.030362 15048 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:55.030465 15049 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:55.030606 14736 server_base.cc:1061] running on GCE node
W20260812 06:19:55.030617 15055 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:55.030853 14736 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:55.030893 14736 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:55.030910 14736 hybrid_clock.cc:648] HybridClock initialized: now 1786515595030910 us; error 0 us; skew 500 ppm
I20260812 06:19:55.031682 14736 webserver.cc:533] Webserver started at http://127.14.100.62:43771/ using document root <none> and password file <none>
I20260812 06:19:55.031827 14736 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:55.031872 14736 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:55.031945 14736 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:55.032294 14736 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/master-0-root/instance:
uuid: "87430757a6cb47a89e45d080879db6b1"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-bndk"
I20260812 06:19:55.033710 14736 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:55.034516 15062 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:55.034706 14736 fs_manager.cc:730] Time spent opening block manager: real 0.000s	user 0.001s	sys 0.000s
I20260812 06:19:55.034773 14736 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/master-0-root
uuid: "87430757a6cb47a89e45d080879db6b1"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-bndk"
I20260812 06:19:55.034839 14736 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-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:55.042831 14736 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:55.043116 14736 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:55.046787 14736 rpc_server.cc:307] RPC server started. Bound to: 127.14.100.62:36883
I20260812 06:19:55.052430 15152 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.100.62:36883 every 8 connection(s)
I20260812 06:19:55.052839 15155 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:55.054422 15155 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1: Bootstrap starting.
I20260812 06:19:55.055091 15155 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:55.055958 15155 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1: No bootstrap required, opened a new log
I20260812 06:19:55.056293 15155 raft_consensus.cc:359] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87430757a6cb47a89e45d080879db6b1" member_type: VOTER }
I20260812 06:19:55.056370 15155 raft_consensus.cc:385] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:55.056396 15155 raft_consensus.cc:740] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 87430757a6cb47a89e45d080879db6b1, State: Initialized, Role: FOLLOWER
I20260812 06:19:55.056506 15155 consensus_queue.cc:260] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [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: "87430757a6cb47a89e45d080879db6b1" member_type: VOTER }
I20260812 06:19:55.056564 15155 raft_consensus.cc:399] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:55.056591 15155 raft_consensus.cc:493] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:55.056622 15155 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:55.057196 15155 raft_consensus.cc:515] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87430757a6cb47a89e45d080879db6b1" member_type: VOTER }
I20260812 06:19:55.057336 15155 leader_election.cc:304] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [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: 87430757a6cb47a89e45d080879db6b1; no voters: 
I20260812 06:19:55.057476 15155 leader_election.cc:290] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:55.057576 15159 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:55.057749 15159 raft_consensus.cc:697] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 1 LEADER]: Becoming Leader. State: Replica: 87430757a6cb47a89e45d080879db6b1, State: Running, Role: LEADER
I20260812 06:19:55.057871 15155 sys_catalog.cc:565] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:55.057875 15159 consensus_queue.cc:237] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [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: "87430757a6cb47a89e45d080879db6b1" member_type: VOTER }
I20260812 06:19:55.058313 15160 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "87430757a6cb47a89e45d080879db6b1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87430757a6cb47a89e45d080879db6b1" member_type: VOTER } }
I20260812 06:19:55.058462 15160 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:55.058334 15161 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 87430757a6cb47a89e45d080879db6b1. Latest consensus state: current_term: 1 leader_uuid: "87430757a6cb47a89e45d080879db6b1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87430757a6cb47a89e45d080879db6b1" member_type: VOTER } }
I20260812 06:19:55.058704 15161 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:55.058719 15165 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:55.059473 15165 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:55.059649 14736 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:55.061092 15165 catalog_manager.cc:1383] Generated new cluster ID: 0a6cc86da7a04086861f15f561fc12e5
I20260812 06:19:55.061139 15165 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:55.077183 15165 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:55.077702 15165 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:55.085683 15165 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1: Generated new TSK 0
I20260812 06:19:55.085822 15165 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:55.091670 14736 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:55.093318 15192 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:55.093420 14736 server_base.cc:1061] running on GCE node
W20260812 06:19:55.093381 15193 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:55.093559 15199 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:55.093755 14736 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:55.093796 14736 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:55.093811 14736 hybrid_clock.cc:648] HybridClock initialized: now 1786515595093810 us; error 0 us; skew 500 ppm
I20260812 06:19:55.094559 14736 webserver.cc:533] Webserver started at http://127.14.100.1:45015/ using document root <none> and password file <none>
I20260812 06:19:55.094705 14736 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:55.094749 14736 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:55.094820 14736 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:55.095142 14736 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/instance:
uuid: "bc727172df644aacb9b6e2e4343288f6"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-bndk"
I20260812 06:19:55.096460 14736 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:55.097263 15205 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:55.097482 14736 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:55.097555 14736 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root
uuid: "bc727172df644aacb9b6e2e4343288f6"
format_stamp: "Formatted at 2026-08-12 06:19:55 on dist-test-slave-bndk"
I20260812 06:19:55.097608 14736 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-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:55.112485 14736 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:55.112766 14736 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:55.112991 14736 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:55.113427 14736 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:55.113463 14736 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:55.113504 14736 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:55.113524 14736 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:55.117368 14736 rpc_server.cc:307] RPC server started. Bound to: 127.14.100.1:34701
I20260812 06:19:55.118903 15319 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.100.1:34701 every 8 connection(s)
I20260812 06:19:55.125798 15320 heartbeater.cc:344] Connected to a master server at 127.14.100.62:36883
I20260812 06:19:55.125880 15320 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:55.126049 15320 heartbeater.cc:507] Master 127.14.100.62:36883 requested a full tablet report, sending...
I20260812 06:19:55.126559 15096 ts_manager.cc:194] Registered new tserver with Master: bc727172df644aacb9b6e2e4343288f6 (127.14.100.1:34701)
I20260812 06:19:55.126741 14736 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008758211s
I20260812 06:19:55.127264 15096 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52254
I20260812 06:19:55.132575 15096 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52256:
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:55.140149 15258 tablet_service.cc:1511] Processing CreateTablet for tablet deb63b3ea0d543c880a577435bfe5535 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6c7dc80908374d82b9c0982dc115c0a2]), partition=
I20260812 06:19:55.140378 15258 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet deb63b3ea0d543c880a577435bfe5535. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:55.142172 15343 tablet_bootstrap.cc:492] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Bootstrap starting.
I20260812 06:19:55.143103 15343 tablet_bootstrap.cc:654] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:55.144033 15343 tablet_bootstrap.cc:492] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: No bootstrap required, opened a new log
I20260812 06:19:55.144104 15343 ts_tablet_manager.cc:1403] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:55.144470 15343 raft_consensus.cc:359] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc727172df644aacb9b6e2e4343288f6" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 34701 } }
I20260812 06:19:55.144556 15343 raft_consensus.cc:385] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:55.144591 15343 raft_consensus.cc:740] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bc727172df644aacb9b6e2e4343288f6, State: Initialized, Role: FOLLOWER
I20260812 06:19:55.144712 15343 consensus_queue.cc:260] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [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: "bc727172df644aacb9b6e2e4343288f6" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 34701 } }
I20260812 06:19:55.144779 15343 raft_consensus.cc:399] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:55.144815 15343 raft_consensus.cc:493] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:55.144862 15343 raft_consensus.cc:3060] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:55.145689 15343 raft_consensus.cc:515] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc727172df644aacb9b6e2e4343288f6" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 34701 } }
I20260812 06:19:55.145817 15343 leader_election.cc:304] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [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: bc727172df644aacb9b6e2e4343288f6; no voters: 
I20260812 06:19:55.146005 15343 leader_election.cc:290] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:55.146097 15345 raft_consensus.cc:2804] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:55.146302 15320 heartbeater.cc:499] Master 127.14.100.62:36883 was elected leader, sending a full tablet report...
I20260812 06:19:55.146282 15345 raft_consensus.cc:697] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 1 LEADER]: Becoming Leader. State: Replica: bc727172df644aacb9b6e2e4343288f6, State: Running, Role: LEADER
I20260812 06:19:55.146286 15343 ts_tablet_manager.cc:1434] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:55.146454 15345 consensus_queue.cc:237] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [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: "bc727172df644aacb9b6e2e4343288f6" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 34701 } }
I20260812 06:19:55.147687 15096 catalog_manager.cc:5719] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 reported cstate change: term changed from 0 to 1, leader changed from <none> to bc727172df644aacb9b6e2e4343288f6 (127.14.100.1). New cstate: current_term: 1 leader_uuid: "bc727172df644aacb9b6e2e4343288f6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc727172df644aacb9b6e2e4343288f6" member_type: VOTER last_known_addr { host: "127.14.100.1" port: 34701 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:55.200629 14736 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.013s	sys 0.008s
I20260812 06:19:55.369403 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushMRSOp(deb63b3ea0d543c880a577435bfe5535): perf score=23.023690
I20260812 06:19:55.531669 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushMRSOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.162s	user 0.143s	sys 0.016s Metrics: {"bytes_written":13168992,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":833,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44499,"lbm_writes_lt_1ms":878,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1605}
I20260812 06:19:55.532321 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling LogGCOp(deb63b3ea0d543c880a577435bfe5535): free 20743880 bytes of WAL
I20260812 06:19:55.532567 15211 log_reader.cc:385] T deb63b3ea0d543c880a577435bfe5535: removed 2 log segments from log reader
I20260812 06:19:55.532616 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000001 (ops 1-6)
I20260812 06:19:55.532656 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000002 (ops 7-11)
I20260812 06:19:55.536620 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: LogGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:55.536976 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535): 20513812 bytes on disk
I20260812 06:19:55.537384 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:55.537797 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:55.555135 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":4559,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:55.555471 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:55.565070 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.565416 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:55.725404 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.160s	user 0.114s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815776,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":856,"lbm_read_time_us":11894,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26076,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":349,"threads_started":5,"update_count":2500}
I20260812 06:19:55.725927 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:55.771530 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.045s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409938,"delete_count":0,"lbm_write_time_us":18419,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.772015 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:55.786849 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5679,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.787340 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:55.936299 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.149s	user 0.117s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":9148,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26070,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:19:55.936880 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:55.986384 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.049s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21951,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.986940 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:56.131440 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.144s	user 0.106s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":858,"lbm_read_time_us":9615,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23844,"lbm_writes_lt_1ms":443,"mutex_wait_us":313,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:19:56.132000 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:56.182700 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.051s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18210,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.183183 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:56.192876 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.193293 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:56.358309 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.165s	user 0.115s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1036,"lbm_read_time_us":12393,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26404,"lbm_writes_lt_1ms":543,"mutex_wait_us":571,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:19:56.358850 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=11.118625
I20260812 06:19:56.387362 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.028s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12717742,"delete_count":0,"lbm_write_time_us":11723,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:56.387972 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:56.410713 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.023s	user 0.003s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4822,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.411868 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:56.420786 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.009s	user 0.000s	sys 0.003s Metrics: {"bytes_written":1271931,"delete_count":0,"lbm_write_time_us":1155,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:19:56.421195 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.196750
I20260812 06:19:56.431406 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3838,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:56.431762 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:56.602293 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.170s	user 0.109s	sys 0.060s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24815826,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":303,"lbm_read_time_us":12139,"lbm_reads_lt_1ms":574,"lbm_write_time_us":28853,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":556800,"update_count":2500}
I20260812 06:19:56.602905 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=11.118625
I20260812 06:19:56.630940 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.028s	user 0.019s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11381,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:56.632222 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:56.657105 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.025s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5299,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.657601 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:56.675042 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.017s	user 0.001s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.675459 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushMRSOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:56.716187 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushMRSOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.041s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1402,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1420,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:56.716777 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling LogGCOp(deb63b3ea0d543c880a577435bfe5535): free 121006441 bytes of WAL
I20260812 06:19:56.716979 15211 log_reader.cc:385] T deb63b3ea0d543c880a577435bfe5535: removed 12 log segments from log reader
I20260812 06:19:56.717033 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000003 (ops 12-16)
I20260812 06:19:56.717060 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000004 (ops 17-21)
I20260812 06:19:56.717087 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000005 (ops 22-26)
I20260812 06:19:56.717118 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000006 (ops 27-31)
I20260812 06:19:56.717149 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000007 (ops 32-36)
I20260812 06:19:56.717182 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000008 (ops 37-40)
I20260812 06:19:56.717237 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000009 (ops 41-45)
I20260812 06:19:56.717272 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000010 (ops 46-50)
I20260812 06:19:56.717293 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000011 (ops 51-55)
I20260812 06:19:56.717324 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000012 (ops 56-60)
I20260812 06:19:56.717357 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000013 (ops 61-65)
I20260812 06:19:56.717389 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000014 (ops 66-70)
I20260812 06:19:56.737638 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: LogGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.021s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:19:56.738159 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535): 462 bytes on disk
I20260812 06:19:56.738574 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.739100 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:56.760802 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.022s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.761200 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:56.770524 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.770985 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:56.998812 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.228s	user 0.144s	sys 0.075s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020855,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":431,"lbm_read_time_us":13987,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35586,"lbm_writes_lt_1ms":743,"mutex_wait_us":58,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:19:56.999302 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=18.063937
I20260812 06:19:57.050798 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.051s	user 0.034s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":22959,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:57.051254 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:57.221660 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.170s	user 0.107s	sys 0.056s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815566,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":398,"lbm_read_time_us":11494,"lbm_reads_lt_1ms":563,"lbm_write_time_us":28600,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:57.222129 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=15.087375
I20260812 06:19:57.269289 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.047s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":15750,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:57.269794 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=3.181125
I20260812 06:19:57.281598 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5046214,"delete_count":0,"lbm_write_time_us":4758,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:19:57.282016 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.196750
I20260812 06:19:57.289084 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":2628,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:57.289505 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:57.484987 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.195s	user 0.119s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918181,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":636,"lbm_read_time_us":13285,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33502,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:19:57.485554 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:57.533960 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.048s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20481,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.534634 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:57.550401 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.550889 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:57.724893 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.174s	user 0.115s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":799,"lbm_read_time_us":11808,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29706,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:19:57.725659 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:57.781265 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.055s	user 0.020s	sys 0.030s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26122,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.781796 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:57.794210 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.794750 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:57.953307 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.158s	user 0.109s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":12249,"lbm_reads_lt_1ms":564,"lbm_write_time_us":24581,"lbm_writes_lt_1ms":543,"mutex_wait_us":248,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:57.953760 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:58.004329 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.050s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18950,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.004889 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:58.014688 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.015089 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushMRSOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:58.042753 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushMRSOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1263,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1233,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":896}
I20260812 06:19:58.043401 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:58.209404 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.166s	user 0.109s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":446,"lbm_read_time_us":12028,"lbm_reads_lt_1ms":564,"lbm_write_time_us":24672,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2500}
I20260812 06:19:58.210135 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling LogGCOp(deb63b3ea0d543c880a577435bfe5535): free 111786266 bytes of WAL
I20260812 06:19:58.210424 15211 log_reader.cc:385] T deb63b3ea0d543c880a577435bfe5535: removed 11 log segments from log reader
I20260812 06:19:58.210510 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000015 (ops 71-74)
I20260812 06:19:58.210562 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000016 (ops 75-79)
I20260812 06:19:58.210602 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000017 (ops 80-84)
I20260812 06:19:58.210691 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000018 (ops 85-89)
I20260812 06:19:58.210740 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000019 (ops 90-94)
I20260812 06:19:58.210813 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000020 (ops 95-98)
I20260812 06:19:58.210863 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000021 (ops 99-103)
I20260812 06:19:58.210929 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000022 (ops 104-108)
I20260812 06:19:58.210971 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000023 (ops 109-113)
I20260812 06:19:58.211004 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000024 (ops 114-118)
I20260812 06:19:58.211037 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000025 (ops 119-123)
I20260812 06:19:58.234424 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: LogGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:58.234838 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=18.063937
I20260812 06:19:58.287810 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.053s	user 0.035s	sys 0.015s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":20803,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:58.288290 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:58.298225 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.298704 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535): 447 bytes on disk
I20260812 06:19:58.299103 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.299659 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:58.481914 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.182s	user 0.119s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":13585,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30649,"lbm_writes_lt_1ms":643,"mutex_wait_us":4,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3000}
I20260812 06:19:58.482533 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:58.525753 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.043s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19295,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.526289 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:58.539577 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.540091 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:58.698798 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.159s	user 0.093s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":115,"lbm_read_time_us":11062,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25303,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:58.699388 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:58.752525 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.053s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19934,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.753087 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:58.768273 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.768685 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:58.926682 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.158s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":625,"lbm_read_time_us":10126,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25752,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2500}
I20260812 06:19:58.927184 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:58.974388 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.047s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20831,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.974897 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:58.992406 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.017s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4289,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.992838 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:59.155292 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.162s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":11519,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26461,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:19:59.155757 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:59.195096 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.039s	user 0.026s	sys 0.011s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":16615,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.195639 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:59.211508 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.212030 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:59.376605 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.164s	user 0.099s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":9105,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26759,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:59.377153 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=14.095187
I20260812 06:19:59.422655 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.045s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17627,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.423225 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:59.433409 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.433905 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushMRSOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:59.459249 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushMRSOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.025s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":379,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1270,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1414,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:59.460013 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling LogGCOp(deb63b3ea0d543c880a577435bfe5535): free 132571568 bytes of WAL
I20260812 06:19:59.460232 15211 log_reader.cc:385] T deb63b3ea0d543c880a577435bfe5535: removed 13 log segments from log reader
I20260812 06:19:59.460281 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000026 (ops 124-128)
I20260812 06:19:59.460316 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000027 (ops 129-132)
I20260812 06:19:59.460346 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000028 (ops 133-137)
I20260812 06:19:59.460379 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000029 (ops 138-142)
I20260812 06:19:59.460410 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000030 (ops 143-147)
I20260812 06:19:59.460443 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000031 (ops 148-152)
I20260812 06:19:59.460474 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000032 (ops 153-157)
I20260812 06:19:59.460505 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000033 (ops 158-162)
I20260812 06:19:59.460536 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000034 (ops 163-167)
I20260812 06:19:59.460566 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000035 (ops 168-172)
I20260812 06:19:59.460597 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000036 (ops 173-177)
I20260812 06:19:59.460628 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000037 (ops 178-182)
I20260812 06:19:59.460657 15211 log.cc:1079] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: Deleting log segment in path: /tmp/dist-test-task1NECaX/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590114795-14736-0/minicluster-data/ts-0-root/wals/deb63b3ea0d543c880a577435bfe5535/wal-000000038 (ops 183-186)
I20260812 06:19:59.482558 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: LogGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:59.486871 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535): 482 bytes on disk
I20260812 06:19:59.487391 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: UndoDeltaBlockGCOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:19:59.488077 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:59.508822 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.509234 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=2.188937
I20260812 06:19:59.518541 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3574,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.518891 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:59.744019 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.225s	user 0.182s	sys 0.041s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":540,"lbm_read_time_us":14779,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35061,"lbm_writes_lt_1ms":743,"mutex_wait_us":70,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:19:59.747159 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=17.071750
I20260812 06:19:59.757469 14736 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.557s	user 1.606s	sys 0.166s
I20260812 06:19:59.804831 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.057s	user 0.026s	sys 0.028s Metrics: {"bytes_written":18666228,"delete_count":0,"lbm_write_time_us":25279,"lbm_writes_lt_1ms":458,"reinsert_count":0,"update_count":2275}
I20260812 06:19:59.805384 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:59.808580 14736 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.051s	user 0.001s	sys 0.000s
I20260812 06:19:59.808972 14736 tablet_server.cc:179] TabletServer@127.14.100.1:0 shutting down...
I20260812 06:19:59.812187 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: FlushDeltaMemStoresOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":1952,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:19:59.812650 15325 maintenance_manager.cc:419] P bc727172df644aacb9b6e2e4343288f6: Scheduling MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535): perf score=1.000000
I20260812 06:19:59.939311 15211 maintenance_manager.cc:643] P bc727172df644aacb9b6e2e4343288f6: MajorDeltaCompactionOp(deb63b3ea0d543c880a577435bfe5535) complete. Timing: real 0.126s	user 0.103s	sys 0.023s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512244,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":7321,"lbm_reads_lt_1ms":518,"lbm_write_time_us":21296,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:59.939922 14736 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:59.940145 14736 tablet_replica.cc:333] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6: stopping tablet replica
I20260812 06:19:59.940275 14736 raft_consensus.cc:2243] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.940424 14736 raft_consensus.cc:2272] T deb63b3ea0d543c880a577435bfe5535 P bc727172df644aacb9b6e2e4343288f6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.943475 14736 tablet_server.cc:196] TabletServer@127.14.100.1:0 shutdown complete.
I20260812 06:19:59.983673 14736 master.cc:562] Master@127.14.100.62:36883 shutting down...
I20260812 06:19:59.986743 14736 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.986918 14736 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.986987 14736 tablet_replica.cc:333] T 00000000000000000000000000000000 P 87430757a6cb47a89e45d080879db6b1: stopping tablet replica
I20260812 06:19:59.989908 14736 master.cc:584] Master@127.14.100.62:36883 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5032 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9936 ms total)

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