[==========] 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:17:14.498762 21728 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.56.62:40961
I20260812 06:17:14.500026 21728 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:17:14.500710 21728 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.507653 21734 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:17:14.507643 21736 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:17:14.507786 21728 server_base.cc:1061] running on GCE node
W20260812 06:17:14.507643 21733 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:17:14.508414 21728 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.508515 21728 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:17:14.508546 21728 hybrid_clock.cc:648] HybridClock initialized: now 1786515434508545 us; error 0 us; skew 500 ppm
I20260812 06:17:14.510795 21728 webserver.cc:533] Webserver started at http://127.21.56.62:45431/ using document root <none> and password file <none>
I20260812 06:17:14.511474 21728 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.511554 21728 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.511794 21728 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.513639 21728 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/master-0-root/instance:
uuid: "37509cd69a0047e88d1eb92edc7b8b12"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-btw8"
I20260812 06:17:14.517944 21728 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:17:14.520885 21741 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:17:14.522122 21728 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:14.522248 21728 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/master-0-root
uuid: "37509cd69a0047e88d1eb92edc7b8b12"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-btw8"
I20260812 06:17:14.522351 21728 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-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:17:14.556262 21728 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.556954 21728 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:17:14.557108 21728 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.566463 21728 rpc_server.cc:307] RPC server started. Bound to: 127.21.56.62:40961
I20260812 06:17:14.566473 21798 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.56.62:40961 every 8 connection(s)
I20260812 06:17:14.569147 21799 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:17:14.575985 21799 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12: Bootstrap starting.
I20260812 06:17:14.579123 21799 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:14.580612 21799 log.cc:826] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:14.582875 21799 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12: No bootstrap required, opened a new log
I20260812 06:17:14.586136 21799 raft_consensus.cc:359] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37509cd69a0047e88d1eb92edc7b8b12" member_type: VOTER }
I20260812 06:17:14.586396 21799 raft_consensus.cc:385] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:14.586501 21799 raft_consensus.cc:740] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 37509cd69a0047e88d1eb92edc7b8b12, State: Initialized, Role: FOLLOWER
I20260812 06:17:14.587252 21799 consensus_queue.cc:260] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [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: "37509cd69a0047e88d1eb92edc7b8b12" member_type: VOTER }
I20260812 06:17:14.587491 21799 raft_consensus.cc:399] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:14.587592 21799 raft_consensus.cc:493] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:14.587754 21799 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:14.588768 21799 raft_consensus.cc:515] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37509cd69a0047e88d1eb92edc7b8b12" member_type: VOTER }
I20260812 06:17:14.589284 21799 leader_election.cc:304] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [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: 37509cd69a0047e88d1eb92edc7b8b12; no voters: 
I20260812 06:17:14.589671 21799 leader_election.cc:290] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:14.589967 21802 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:14.590333 21802 raft_consensus.cc:697] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 1 LEADER]: Becoming Leader. State: Replica: 37509cd69a0047e88d1eb92edc7b8b12, State: Running, Role: LEADER
I20260812 06:17:14.590816 21802 consensus_queue.cc:237] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [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: "37509cd69a0047e88d1eb92edc7b8b12" member_type: VOTER }
I20260812 06:17:14.590953 21799 sys_catalog.cc:565] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:14.593468 21805 sys_catalog.cc:455] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 37509cd69a0047e88d1eb92edc7b8b12. Latest consensus state: current_term: 1 leader_uuid: "37509cd69a0047e88d1eb92edc7b8b12" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37509cd69a0047e88d1eb92edc7b8b12" member_type: VOTER } }
I20260812 06:17:14.593442 21804 sys_catalog.cc:455] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "37509cd69a0047e88d1eb92edc7b8b12" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "37509cd69a0047e88d1eb92edc7b8b12" member_type: VOTER } }
I20260812 06:17:14.593636 21805 sys_catalog.cc:458] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.593653 21804 sys_catalog.cc:458] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.594177 21728 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:14.596403 21819 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:14.596494 21819 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:14.596601 21817 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:14.597401 21817 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:14.603076 21817 catalog_manager.cc:1383] Generated new cluster ID: 2156370103a444bb8300d60ad0ca11c5
I20260812 06:17:14.603183 21817 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:14.611698 21817 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:14.612946 21817 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:14.623891 21817 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12: Generated new TSK 0
I20260812 06:17:14.624825 21817 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:14.627087 21728 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.630810 21825 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:17:14.631003 21824 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:17:14.631150 21728 server_base.cc:1061] running on GCE node
W20260812 06:17:14.631327 21827 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:17:14.631623 21728 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.631673 21728 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:17:14.631692 21728 hybrid_clock.cc:648] HybridClock initialized: now 1786515434631693 us; error 0 us; skew 500 ppm
I20260812 06:17:14.632936 21728 webserver.cc:533] Webserver started at http://127.21.56.1:39985/ using document root <none> and password file <none>
I20260812 06:17:14.633160 21728 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.633219 21728 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.633327 21728 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.633786 21728 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/instance:
uuid: "9c7a8297b89f454b99e8080d487b242c"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-btw8"
I20260812 06:17:14.635660 21728 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:14.636875 21832 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:17:14.637202 21728 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:14.637305 21728 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root
uuid: "9c7a8297b89f454b99e8080d487b242c"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-btw8"
I20260812 06:17:14.637403 21728 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-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:17:14.653195 21728 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.654426 21728 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.655117 21728 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:14.656127 21728 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:14.656186 21728 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.656297 21728 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:14.656337 21728 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.664124 21728 rpc_server.cc:307] RPC server started. Bound to: 127.21.56.1:36375
I20260812 06:17:14.664204 21902 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.56.1:36375 every 8 connection(s)
I20260812 06:17:14.676929 21903 heartbeater.cc:344] Connected to a master server at 127.21.56.62:40961
I20260812 06:17:14.677265 21903 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:14.677896 21903 heartbeater.cc:507] Master 127.21.56.62:40961 requested a full tablet report, sending...
I20260812 06:17:14.679898 21759 ts_manager.cc:194] Registered new tserver with Master: 9c7a8297b89f454b99e8080d487b242c (127.21.56.1:36375)
I20260812 06:17:14.680027 21728 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015086184s
I20260812 06:17:14.681373 21759 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40746
I20260812 06:17:14.693751 21759 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40756:
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:17:14.711004 21866 tablet_service.cc:1511] Processing CreateTablet for tablet db46a04f98014851a12e24b08cccbb47 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e7558c5615a7459da83f135e4f9b65e4]), partition=
I20260812 06:17:14.711645 21866 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet db46a04f98014851a12e24b08cccbb47. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:14.714775 21916 tablet_bootstrap.cc:492] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Bootstrap starting.
I20260812 06:17:14.716168 21916 tablet_bootstrap.cc:654] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:14.717818 21916 tablet_bootstrap.cc:492] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: No bootstrap required, opened a new log
I20260812 06:17:14.718016 21916 ts_tablet_manager.cc:1403] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:14.718775 21916 raft_consensus.cc:359] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c7a8297b89f454b99e8080d487b242c" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36375 } }
I20260812 06:17:14.718933 21916 raft_consensus.cc:385] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:14.718988 21916 raft_consensus.cc:740] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9c7a8297b89f454b99e8080d487b242c, State: Initialized, Role: FOLLOWER
I20260812 06:17:14.719167 21916 consensus_queue.cc:260] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [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: "9c7a8297b89f454b99e8080d487b242c" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36375 } }
I20260812 06:17:14.719308 21916 raft_consensus.cc:399] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:14.719393 21916 raft_consensus.cc:493] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:14.719456 21916 raft_consensus.cc:3060] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:14.720773 21916 raft_consensus.cc:515] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c7a8297b89f454b99e8080d487b242c" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36375 } }
I20260812 06:17:14.720973 21916 leader_election.cc:304] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [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: 9c7a8297b89f454b99e8080d487b242c; no voters: 
I20260812 06:17:14.721271 21916 leader_election.cc:290] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:14.721408 21919 raft_consensus.cc:2804] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:14.721695 21919 raft_consensus.cc:697] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 1 LEADER]: Becoming Leader. State: Replica: 9c7a8297b89f454b99e8080d487b242c, State: Running, Role: LEADER
I20260812 06:17:14.721752 21916 ts_tablet_manager.cc:1434] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Time spent starting tablet: real 0.004s	user 0.001s	sys 0.003s
I20260812 06:17:14.721947 21919 consensus_queue.cc:237] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [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: "9c7a8297b89f454b99e8080d487b242c" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36375 } }
I20260812 06:17:14.722167 21903 heartbeater.cc:499] Master 127.21.56.62:40961 was elected leader, sending a full tablet report...
I20260812 06:17:14.725405 21759 catalog_manager.cc:5719] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c reported cstate change: term changed from 0 to 1, leader changed from <none> to 9c7a8297b89f454b99e8080d487b242c (127.21.56.1). New cstate: current_term: 1 leader_uuid: "9c7a8297b89f454b99e8080d487b242c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c7a8297b89f454b99e8080d487b242c" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36375 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:14.801538 21728 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.069s	user 0.028s	sys 0.004s
I20260812 06:17:14.915699 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushMRSOp(db46a04f98014851a12e24b08cccbb47): perf score=15.086190
I20260812 06:17:15.055850 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushMRSOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.140s	user 0.118s	sys 0.016s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":242,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1146,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":32707,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":142,"threads_started":1,"update_count":1000}
I20260812 06:17:15.057351 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:15.162197 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.105s	user 0.092s	sys 0.012s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12426369,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":486,"lbm_read_time_us":5396,"lbm_reads_lt_1ms":263,"lbm_write_time_us":19669,"lbm_writes_lt_1ms":243,"mutex_wait_us":76,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":20736,"thread_start_us":355,"threads_started":5,"update_count":1000}
I20260812 06:17:15.163118 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling LogGCOp(db46a04f98014851a12e24b08cccbb47): free 8725963 bytes of WAL
I20260812 06:17:15.163614 21838 log_reader.cc:385] T db46a04f98014851a12e24b08cccbb47: removed 1 log segments from log reader
I20260812 06:17:15.163703 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000001 (ops 1-6)
I20260812 06:17:15.165995 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: LogGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.003s	user 0.001s	sys 0.000s Metrics: {"spinlock_wait_cycles":11520}
I20260812 06:17:15.166493 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47): 12308958 bytes on disk
I20260812 06:17:15.167210 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.167919 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=7.149875
I20260812 06:17:15.202133 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.034s	user 0.028s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14636,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:15.202705 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:15.215701 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4602,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.216259 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:15.357048 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.141s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1008,"lbm_read_time_us":9685,"lbm_reads_lt_1ms":372,"lbm_write_time_us":23453,"lbm_writes_lt_1ms":343,"mutex_wait_us":388,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1500}
I20260812 06:17:15.357628 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:15.408571 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.051s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16620,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.409096 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:15.424160 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.424786 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:15.571218 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.146s	user 0.105s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":11096,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25978,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:17:15.572072 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:15.625064 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.053s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18227,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.625563 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:15.638329 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.638921 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:15.761847 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.123s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":424,"lbm_read_time_us":9302,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23811,"lbm_writes_lt_1ms":443,"mutex_wait_us":97,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:17:15.762511 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:15.819612 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.057s	user 0.019s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18863,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.820174 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:15.831875 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.832446 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:15.982931 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.150s	user 0.110s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":11646,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25634,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.984297 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:16.020334 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.036s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15702,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.020936 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:16.138631 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.117s	user 0.085s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528784,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":380,"lbm_read_time_us":7018,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22149,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.139467 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:16.188472 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.049s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16380,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.189014 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:16.200592 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.201231 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:16.324199 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.123s	user 0.107s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":382,"lbm_read_time_us":8672,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22949,"lbm_writes_lt_1ms":443,"mutex_wait_us":5,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:17:16.324847 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:16.379952 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.055s	user 0.036s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18232,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.380577 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:16.396644 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.397306 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushMRSOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:16.429234 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushMRSOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.032s	user 0.022s	sys 0.008s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1765,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1967,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1280}
I20260812 06:17:16.430228 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:16.585783 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.155s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":749,"lbm_read_time_us":10463,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26840,"lbm_writes_lt_1ms":443,"mutex_wait_us":319,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:17:16.586547 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling LogGCOp(db46a04f98014851a12e24b08cccbb47): free 123804181 bytes of WAL
I20260812 06:17:16.586853 21838 log_reader.cc:385] T db46a04f98014851a12e24b08cccbb47: removed 12 log segments from log reader
I20260812 06:17:16.586931 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000002 (ops 7-11)
I20260812 06:17:16.586987 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000003 (ops 12-16)
I20260812 06:17:16.587030 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000004 (ops 17-20)
I20260812 06:17:16.587072 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000005 (ops 21-25)
I20260812 06:17:16.587116 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000006 (ops 26-30)
I20260812 06:17:16.587158 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000007 (ops 31-35)
I20260812 06:17:16.587209 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000008 (ops 36-40)
I20260812 06:17:16.587257 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000009 (ops 41-45)
I20260812 06:17:16.587301 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000010 (ops 46-50)
I20260812 06:17:16.587343 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000011 (ops 51-54)
I20260812 06:17:16.587414 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000012 (ops 55-59)
I20260812 06:17:16.587457 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000013 (ops 60-64)
I20260812 06:17:16.617661 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: LogGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:16.618285 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=14.095187
I20260812 06:17:16.670007 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.051s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23274,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.670674 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47): 446 bytes on disk
I20260812 06:17:16.671197 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.671876 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:16.685662 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5022,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.686230 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:16.871575 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.185s	user 0.122s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1833,"lbm_read_time_us":13152,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29911,"lbm_writes_lt_1ms":543,"mutex_wait_us":1310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:17:16.872259 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=11.118625
I20260812 06:17:16.913580 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.041s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17365,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:16.914287 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:16.933282 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6556,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.933926 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:17.066632 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.132s	user 0.112s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":687,"lbm_read_time_us":8385,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27815,"lbm_writes_lt_1ms":443,"mutex_wait_us":353,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:17.067309 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:17.111979 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.044s	user 0.033s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.112550 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:17.126317 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.126936 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:17.260840 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.134s	user 0.105s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":8286,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26769,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1270656,"update_count":2000}
I20260812 06:17:17.261607 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:17.317365 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.056s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19879,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.317991 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:17.335678 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.017s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.336377 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:17.507030 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.170s	user 0.110s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":413,"lbm_read_time_us":12129,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29050,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:17:17.507752 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:17.558712 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.051s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20951,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.559294 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:17.575125 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.576035 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:17.711520 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.135s	user 0.114s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1271,"lbm_read_time_us":8887,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28283,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.712231 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:17.759467 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.047s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15249,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.760107 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:17.776898 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.017s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.777815 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:17.912367 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.134s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1103,"dirs.run_cpu_time_us":456,"dirs.run_wall_time_us":4309,"lbm_read_time_us":8922,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26126,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:17.913123 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:17.967074 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.054s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17302,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.967746 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:17.979753 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.980288 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushMRSOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:18.011864 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushMRSOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1526,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1445,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:18.012701 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:18.174522 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.162s	user 0.105s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":872,"lbm_read_time_us":11072,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25850,"lbm_writes_lt_1ms":443,"mutex_wait_us":88,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:18.175283 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling LogGCOp(db46a04f98014851a12e24b08cccbb47): free 112692368 bytes of WAL
I20260812 06:17:18.175700 21838 log_reader.cc:385] T db46a04f98014851a12e24b08cccbb47: removed 11 log segments from log reader
I20260812 06:17:18.175789 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000014 (ops 65-69)
I20260812 06:17:18.175884 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000015 (ops 70-74)
I20260812 06:17:18.175952 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000016 (ops 75-79)
I20260812 06:17:18.176034 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000017 (ops 80-84)
I20260812 06:17:18.176100 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000018 (ops 85-89)
I20260812 06:17:18.176173 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000019 (ops 90-94)
I20260812 06:17:18.176214 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000020 (ops 95-99)
I20260812 06:17:18.176322 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000021 (ops 100-104)
I20260812 06:17:18.176365 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000022 (ops 105-109)
I20260812 06:17:18.176440 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000023 (ops 110-114)
I20260812 06:17:18.176482 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000024 (ops 115-119)
I20260812 06:17:18.206053 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: LogGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:18.206650 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47): 463 bytes on disk
I20260812 06:17:18.207183 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.207826 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=14.095187
I20260812 06:17:18.257814 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.050s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22276,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.258565 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:18.270954 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4335,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.271564 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:18.452136 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.180s	user 0.117s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1058,"lbm_read_time_us":11832,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29140,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:17:18.453012 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=14.095187
I20260812 06:17:18.504737 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.051s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.505321 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:18.521955 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.522616 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:18.681375 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.159s	user 0.117s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1065,"lbm_read_time_us":12578,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28928,"lbm_writes_lt_1ms":543,"mutex_wait_us":288,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:17:18.682358 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=11.118625
I20260812 06:17:18.718773 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.036s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15113,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:18.719301 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:18.745123 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.026s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5975,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.745745 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:18.761277 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.761957 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:18.932648 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.170s	user 0.131s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733832,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":441,"lbm_read_time_us":12700,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33944,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:17:18.933418 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=11.118625
I20260812 06:17:18.994288 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.061s	user 0.025s	sys 0.025s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":24302,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:18.994969 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:19.008831 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.009416 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:19.020130 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.020677 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:19.186923 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.166s	user 0.126s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":637,"lbm_read_time_us":12737,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33557,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:17:19.187732 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:19.230119 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.042s	user 0.024s	sys 0.014s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18155,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.230805 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:19.241953 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.242558 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:19.391563 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.149s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2857,"lbm_read_time_us":9300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29503,"lbm_writes_lt_1ms":443,"mutex_wait_us":1301,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:17:19.392690 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=10.126437
I20260812 06:17:19.456638 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.064s	user 0.035s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18000,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.457397 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:19.471484 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.472105 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushMRSOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:19.515792 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushMRSOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.043s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1611,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1773,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:19.516582 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling LogGCOp(db46a04f98014851a12e24b08cccbb47): free 116849731 bytes of WAL
I20260812 06:17:19.516832 21838 log_reader.cc:385] T db46a04f98014851a12e24b08cccbb47: removed 12 log segments from log reader
I20260812 06:17:19.516878 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000025 (ops 120-124)
I20260812 06:17:19.516930 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000026 (ops 125-128)
I20260812 06:17:19.516985 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000027 (ops 129-133)
I20260812 06:17:19.517042 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000028 (ops 134-138)
I20260812 06:17:19.517084 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000029 (ops 139-142)
I20260812 06:17:19.517122 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000030 (ops 143-147)
I20260812 06:17:19.517160 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000031 (ops 148-152)
I20260812 06:17:19.517215 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000032 (ops 153-157)
I20260812 06:17:19.517249 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000033 (ops 158-162)
I20260812 06:17:19.517287 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000034 (ops 163-166)
I20260812 06:17:19.517330 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000035 (ops 167-171)
I20260812 06:17:19.517369 21838 log.cc:1079] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/db46a04f98014851a12e24b08cccbb47/wal-000000036 (ops 172-176)
I20260812 06:17:19.545104 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: LogGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:19.545629 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:19.564420 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.564966 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47): 446 bytes on disk
I20260812 06:17:19.565419 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: UndoDeltaBlockGCOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.565980 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=2.188937
I20260812 06:17:19.577564 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.578224 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:19.788589 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.210s	user 0.139s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":304,"lbm_read_time_us":12597,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36992,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:17:19.789731 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=14.095187
I20260812 06:17:19.866559 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.077s	user 0.037s	sys 0.024s Metrics: {"bytes_written":16532974,"delete_count":0,"lbm_write_time_us":25786,"lbm_writes_lt_1ms":406,"mutex_wait_us":903,"reinsert_count":0,"update_count":2015}
I20260812 06:17:19.867239 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=6.157687
I20260812 06:17:19.906268 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.039s	user 0.025s	sys 0.004s Metrics: {"bytes_written":8082009,"delete_count":0,"lbm_write_time_us":13596,"lbm_writes_lt_1ms":200,"reinsert_count":0,"update_count":985}
I20260812 06:17:19.906973 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:20.061740 21728 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.260s	user 1.985s	sys 0.137s
I20260812 06:17:20.109257 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.202s	user 0.127s	sys 0.073s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836140,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":15384,"lbm_reads_lt_1ms":660,"lbm_write_time_us":34341,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:20.109843 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47): perf score=14.095187
I20260812 06:17:20.147652 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: FlushDeltaMemStoresOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.038s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17210,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.148204 21904 maintenance_manager.cc:419] P 9c7a8297b89f454b99e8080d487b242c: Scheduling MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47): perf score=1.000000
I20260812 06:17:20.155642 21728 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.005s	sys 0.000s
I20260812 06:17:20.156425 21728 tablet_server.cc:179] TabletServer@127.21.56.1:0 shutting down...
I20260812 06:17:20.283746 21838 maintenance_manager.cc:643] P 9c7a8297b89f454b99e8080d487b242c: MajorDeltaCompactionOp(db46a04f98014851a12e24b08cccbb47) complete. Timing: real 0.135s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":356,"lbm_read_time_us":10175,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26090,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:20.284711 21728 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:20.285208 21728 tablet_replica.cc:333] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c: stopping tablet replica
I20260812 06:17:20.285483 21728 raft_consensus.cc:2243] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.285738 21728 raft_consensus.cc:2272] T db46a04f98014851a12e24b08cccbb47 P 9c7a8297b89f454b99e8080d487b242c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.292948 21728 tablet_server.cc:196] TabletServer@127.21.56.1:0 shutdown complete.
I20260812 06:17:20.325538 21728 master.cc:562] Master@127.21.56.62:40961 shutting down...
I20260812 06:17:20.330372 21728 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.330614 21728 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.330726 21728 tablet_replica.cc:333] T 00000000000000000000000000000000 P 37509cd69a0047e88d1eb92edc7b8b12: stopping tablet replica
I20260812 06:17:20.343775 21728 master.cc:584] Master@127.21.56.62:40961 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5947 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:20.445778 21728 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.56.62:38453
I20260812 06:17:20.446156 21728 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:20.448269 21939 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:17:20.448391 21936 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:17:20.448437 21937 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:17:20.448499 21728 server_base.cc:1061] running on GCE node
I20260812 06:17:20.448782 21728 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:20.448846 21728 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:17:20.448871 21728 hybrid_clock.cc:648] HybridClock initialized: now 1786515440448871 us; error 0 us; skew 500 ppm
I20260812 06:17:20.449947 21728 webserver.cc:533] Webserver started at http://127.21.56.62:33173/ using document root <none> and password file <none>
I20260812 06:17:20.450151 21728 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:20.450227 21728 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:20.450306 21728 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:20.450774 21728 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/master-0-root/instance:
uuid: "38abc30d02b04ebf91ec9c82286eeac8"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-btw8"
I20260812 06:17:20.452564 21728 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:20.453625 21944 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:17:20.453948 21728 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:20.454041 21728 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/master-0-root
uuid: "38abc30d02b04ebf91ec9c82286eeac8"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-btw8"
I20260812 06:17:20.454131 21728 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-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:17:20.467636 21728 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:20.468111 21728 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:20.472862 21728 rpc_server.cc:307] RPC server started. Bound to: 127.21.56.62:38453
I20260812 06:17:20.476305 22002 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.56.62:38453 every 8 connection(s)
I20260812 06:17:20.476660 22003 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:17:20.488847 22003 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8: Bootstrap starting.
I20260812 06:17:20.493567 22003 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:20.494940 22003 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8: No bootstrap required, opened a new log
I20260812 06:17:20.495465 22003 raft_consensus.cc:359] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38abc30d02b04ebf91ec9c82286eeac8" member_type: VOTER }
I20260812 06:17:20.495564 22003 raft_consensus.cc:385] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:20.495589 22003 raft_consensus.cc:740] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 38abc30d02b04ebf91ec9c82286eeac8, State: Initialized, Role: FOLLOWER
I20260812 06:17:20.495761 22003 consensus_queue.cc:260] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [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: "38abc30d02b04ebf91ec9c82286eeac8" member_type: VOTER }
I20260812 06:17:20.495860 22003 raft_consensus.cc:399] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:20.495886 22003 raft_consensus.cc:493] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:20.495918 22003 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:20.496680 22003 raft_consensus.cc:515] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38abc30d02b04ebf91ec9c82286eeac8" member_type: VOTER }
I20260812 06:17:20.496803 22003 leader_election.cc:304] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [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: 38abc30d02b04ebf91ec9c82286eeac8; no voters: 
I20260812 06:17:20.496986 22003 leader_election.cc:290] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:20.497189 22007 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:20.497388 22007 raft_consensus.cc:697] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 1 LEADER]: Becoming Leader. State: Replica: 38abc30d02b04ebf91ec9c82286eeac8, State: Running, Role: LEADER
I20260812 06:17:20.497545 22003 sys_catalog.cc:565] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:20.497557 22007 consensus_queue.cc:237] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [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: "38abc30d02b04ebf91ec9c82286eeac8" member_type: VOTER }
I20260812 06:17:20.498234 22009 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 38abc30d02b04ebf91ec9c82286eeac8. Latest consensus state: current_term: 1 leader_uuid: "38abc30d02b04ebf91ec9c82286eeac8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38abc30d02b04ebf91ec9c82286eeac8" member_type: VOTER } }
I20260812 06:17:20.498374 22009 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:20.498437 22008 sys_catalog.cc:455] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "38abc30d02b04ebf91ec9c82286eeac8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38abc30d02b04ebf91ec9c82286eeac8" member_type: VOTER } }
I20260812 06:17:20.498610 22008 sys_catalog.cc:458] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:20.499022 22016 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:20.499816 22016 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:20.500001 21728 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:20.501876 22016 catalog_manager.cc:1383] Generated new cluster ID: 1e9eb6a23ecb4f61a828753514579cf7
I20260812 06:17:20.501945 22016 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:20.506932 22016 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:20.507623 22016 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:20.513942 22016 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8: Generated new TSK 0
I20260812 06:17:20.514129 22016 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:20.516321 21728 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:20.518527 22028 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:17:20.518599 22027 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:17:20.518627 22030 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:17:20.518837 21728 server_base.cc:1061] running on GCE node
I20260812 06:17:20.519153 21728 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:20.519212 21728 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:17:20.519229 21728 hybrid_clock.cc:648] HybridClock initialized: now 1786515440519230 us; error 0 us; skew 500 ppm
I20260812 06:17:20.520351 21728 webserver.cc:533] Webserver started at http://127.21.56.1:46419/ using document root <none> and password file <none>
I20260812 06:17:20.520507 21728 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:20.520648 21728 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:20.520712 21728 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:20.521097 21728 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/instance:
uuid: "0e7a0e20a8e5488e8ed52b3b53b82bba"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-btw8"
I20260812 06:17:20.522886 21728 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:20.524034 22035 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:17:20.524349 21728 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:20.524452 21728 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root
uuid: "0e7a0e20a8e5488e8ed52b3b53b82bba"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-btw8"
I20260812 06:17:20.524546 21728 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-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:17:20.530591 21728 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:20.530992 21728 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:20.531406 21728 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:20.531925 21728 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:20.531985 21728 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:20.532043 21728 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:20.532094 21728 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:20.536383 21728 rpc_server.cc:307] RPC server started. Bound to: 127.21.56.1:36285
I20260812 06:17:20.536443 22103 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.56.1:36285 every 8 connection(s)
I20260812 06:17:20.548982 22104 heartbeater.cc:344] Connected to a master server at 127.21.56.62:38453
I20260812 06:17:20.549189 22104 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:20.549535 22104 heartbeater.cc:507] Master 127.21.56.62:38453 requested a full tablet report, sending...
I20260812 06:17:20.550357 21964 ts_manager.cc:194] Registered new tserver with Master: 0e7a0e20a8e5488e8ed52b3b53b82bba (127.21.56.1:36285)
I20260812 06:17:20.550484 21728 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013631234s
I20260812 06:17:20.551293 21964 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48942
I20260812 06:17:20.558827 21964 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48954:
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:17:20.568596 22066 tablet_service.cc:1511] Processing CreateTablet for tablet 51ccb77ffac44a2c9a4d8723b92c165f (DEFAULT_TABLE table=heavy-update-compaction-test [id=f22f634663174c61a0c1d4468fc3b9cf]), partition=
I20260812 06:17:20.569028 22066 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 51ccb77ffac44a2c9a4d8723b92c165f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:20.571532 22118 tablet_bootstrap.cc:492] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Bootstrap starting.
I20260812 06:17:20.572453 22118 tablet_bootstrap.cc:654] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:20.573598 22118 tablet_bootstrap.cc:492] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: No bootstrap required, opened a new log
I20260812 06:17:20.573696 22118 ts_tablet_manager.cc:1403] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:20.574358 22118 raft_consensus.cc:359] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0e7a0e20a8e5488e8ed52b3b53b82bba" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36285 } }
I20260812 06:17:20.574496 22118 raft_consensus.cc:385] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:20.574554 22118 raft_consensus.cc:740] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0e7a0e20a8e5488e8ed52b3b53b82bba, State: Initialized, Role: FOLLOWER
I20260812 06:17:20.574755 22118 consensus_queue.cc:260] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [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: "0e7a0e20a8e5488e8ed52b3b53b82bba" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36285 } }
I20260812 06:17:20.574855 22118 raft_consensus.cc:399] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:20.574913 22118 raft_consensus.cc:493] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:20.574972 22118 raft_consensus.cc:3060] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:20.575852 22118 raft_consensus.cc:515] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0e7a0e20a8e5488e8ed52b3b53b82bba" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36285 } }
I20260812 06:17:20.576005 22118 leader_election.cc:304] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [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: 0e7a0e20a8e5488e8ed52b3b53b82bba; no voters: 
I20260812 06:17:20.576262 22118 leader_election.cc:290] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:20.576416 22120 raft_consensus.cc:2804] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:20.576656 22118 ts_tablet_manager.cc:1434] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:20.576690 22104 heartbeater.cc:499] Master 127.21.56.62:38453 was elected leader, sending a full tablet report...
I20260812 06:17:20.576682 22120 raft_consensus.cc:697] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 1 LEADER]: Becoming Leader. State: Replica: 0e7a0e20a8e5488e8ed52b3b53b82bba, State: Running, Role: LEADER
I20260812 06:17:20.577059 22120 consensus_queue.cc:237] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [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: "0e7a0e20a8e5488e8ed52b3b53b82bba" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36285 } }
I20260812 06:17:20.578778 21964 catalog_manager.cc:5719] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba reported cstate change: term changed from 0 to 1, leader changed from <none> to 0e7a0e20a8e5488e8ed52b3b53b82bba (127.21.56.1). New cstate: current_term: 1 leader_uuid: "0e7a0e20a8e5488e8ed52b3b53b82bba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0e7a0e20a8e5488e8ed52b3b53b82bba" member_type: VOTER last_known_addr { host: "127.21.56.1" port: 36285 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:20.642894 21728 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.021s	sys 0.004s
I20260812 06:17:20.787458 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=17.070565
I20260812 06:17:20.936247 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.148s	user 0.115s	sys 0.031s Metrics: {"bytes_written":8656349,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1057,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39107,"lbm_writes_lt_1ms":668,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1280,"update_count":1055}
I20260812 06:17:20.937024 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f): free 20743880 bytes of WAL
I20260812 06:17:20.937290 22040 log_reader.cc:385] T 51ccb77ffac44a2c9a4d8723b92c165f: removed 2 log segments from log reader
I20260812 06:17:20.937343 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000001 (ops 1-6)
I20260812 06:17:20.937376 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000002 (ops 7-11)
I20260812 06:17:20.942395 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:20.942955 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:20.971129 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.028s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":6119,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:20.971873 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f): 16411397 bytes on disk
I20260812 06:17:20.972389 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.972836 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:20.984051 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.984669 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:21.148516 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.164s	user 0.123s	sys 0.039s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672388,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":616,"lbm_read_time_us":12524,"lbm_reads_lt_1ms":469,"lbm_write_time_us":26543,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":335,"threads_started":5,"update_count":2000}
I20260812 06:17:21.149215 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:21.196118 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.047s	user 0.038s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20988,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.196672 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:21.209496 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.210055 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:21.346158 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.136s	user 0.107s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":976,"lbm_read_time_us":8686,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26916,"lbm_writes_lt_1ms":443,"mutex_wait_us":304,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2000}
I20260812 06:17:21.351109 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:21.398923 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.047s	user 0.037s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18451,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.399571 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:21.412295 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.412850 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:21.535043 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.122s	user 0.100s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":538,"lbm_read_time_us":8961,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23207,"lbm_writes_lt_1ms":443,"mutex_wait_us":126,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:21.535655 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:21.596387 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.061s	user 0.037s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15793,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.597114 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:21.608894 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.609423 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:21.766064 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.156s	user 0.079s	sys 0.075s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":833,"lbm_read_time_us":11732,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24044,"lbm_writes_lt_1ms":443,"mutex_wait_us":396,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:17:21.766605 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:21.803862 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.037s	user 0.009s	sys 0.026s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14833,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.804390 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:21.916898 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.112s	user 0.091s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":341,"lbm_read_time_us":6696,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20838,"lbm_writes_lt_1ms":343,"mutex_wait_us":23,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":1500}
I20260812 06:17:21.917667 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:21.960777 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.043s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17700,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.961400 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:21.976724 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.978348 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:22.109952 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.131s	user 0.099s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":812,"lbm_read_time_us":9525,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26100,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:17:22.110770 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:22.162012 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.051s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16540,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:22.162633 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:22.173640 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.174247 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:22.337579 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.163s	user 0.107s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":11887,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25913,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.338364 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:22.383420 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.045s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19381,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:22.384043 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:22.396569 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.397171 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:22.430622 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":293,"dirs.run_wall_time_us":1667,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1813,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:22.431411 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f): free 124257240 bytes of WAL
I20260812 06:17:22.431717 22040 log_reader.cc:385] T 51ccb77ffac44a2c9a4d8723b92c165f: removed 12 log segments from log reader
I20260812 06:17:22.431789 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000003 (ops 12-16)
I20260812 06:17:22.431828 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000004 (ops 17-21)
I20260812 06:17:22.431854 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000005 (ops 22-26)
I20260812 06:17:22.431890 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000006 (ops 27-31)
I20260812 06:17:22.431914 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000007 (ops 32-36)
I20260812 06:17:22.431943 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000008 (ops 37-41)
I20260812 06:17:22.431972 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000009 (ops 42-46)
I20260812 06:17:22.431998 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000010 (ops 47-51)
I20260812 06:17:22.432029 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000011 (ops 52-56)
I20260812 06:17:22.432065 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000012 (ops 57-61)
I20260812 06:17:22.432096 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000013 (ops 62-66)
I20260812 06:17:22.432125 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000014 (ops 67-70)
I20260812 06:17:22.462558 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:22.462999 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=3.181125
I20260812 06:17:22.477645 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.014s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4430855,"delete_count":0,"lbm_write_time_us":4596,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:17:22.478179 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f): 482 bytes on disk
I20260812 06:17:22.478720 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.479218 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:22.505914 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.026s	user 0.008s	sys 0.015s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5479,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:22.506577 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:22.719214 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.212s	user 0.136s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877335,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":273,"lbm_read_time_us":15724,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34623,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17920,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:17:22.719975 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=14.095187
I20260812 06:17:22.777776 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.058s	user 0.036s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20155,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.778412 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:22.789947 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.790552 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:22.982638 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.192s	user 0.114s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":13032,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30839,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2500}
I20260812 06:17:22.983588 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=14.095187
I20260812 06:17:23.034545 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.051s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21688,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.035048 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:23.048645 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.049306 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:23.242431 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.193s	user 0.132s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":12588,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28367,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":62848,"update_count":2500}
I20260812 06:17:23.245572 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=14.095187
I20260812 06:17:23.301329 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.056s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23534,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.301851 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:23.313275 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.313943 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:23.468710 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.155s	user 0.117s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":10346,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29271,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:17:23.469519 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:23.506695 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.037s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16097,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.507304 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:23.522148 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5368,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.522713 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:23.655803 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.133s	user 0.097s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":110,"lbm_read_time_us":9136,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25414,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:17:23.656524 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:23.703940 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.047s	user 0.039s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19259,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.704514 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:23.716290 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.717141 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:23.842221 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.125s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":441,"lbm_read_time_us":8346,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24577,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2000}
I20260812 06:17:23.843238 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=10.126437
I20260812 06:17:23.902983 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.059s	user 0.027s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23044,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.904008 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:23.920421 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.921198 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:23.969893 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.048s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":149,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1640,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2035,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:23.970846 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f): free 121006442 bytes of WAL
I20260812 06:17:23.971184 22040 log_reader.cc:385] T 51ccb77ffac44a2c9a4d8723b92c165f: removed 12 log segments from log reader
I20260812 06:17:23.971273 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000015 (ops 71-75)
I20260812 06:17:23.971318 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000016 (ops 76-80)
I20260812 06:17:23.971343 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000017 (ops 81-85)
I20260812 06:17:23.971424 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000018 (ops 86-90)
I20260812 06:17:23.971457 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000019 (ops 91-95)
I20260812 06:17:23.971481 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000020 (ops 96-100)
I20260812 06:17:23.971510 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000021 (ops 101-104)
I20260812 06:17:23.971534 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000022 (ops 105-109)
I20260812 06:17:23.971556 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000023 (ops 110-114)
I20260812 06:17:23.971582 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000024 (ops 115-119)
I20260812 06:17:23.971608 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000025 (ops 120-124)
I20260812 06:17:23.971632 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000026 (ops 125-129)
I20260812 06:17:24.003721 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.033s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:17:24.004191 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f): 462 bytes on disk
I20260812 06:17:24.004704 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.005336 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:24.027529 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.022s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.028090 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:24.039137 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.039932 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:24.259748 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.220s	user 0.148s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":717,"lbm_read_time_us":15292,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35726,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24576,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:17:24.260586 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=15.087375
I20260812 06:17:24.320400 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.059s	user 0.038s	sys 0.020s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":26949,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:17:24.320933 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:24.342818 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.022s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.343333 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:24.355111 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.355857 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:24.569811 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.214s	user 0.140s	sys 0.070s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":303,"lbm_read_time_us":12643,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36451,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":33152,"update_count":3000}
I20260812 06:17:24.570488 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=16.079562
I20260812 06:17:24.640954 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.070s	user 0.030s	sys 0.028s Metrics: {"bytes_written":17681651,"delete_count":0,"lbm_write_time_us":26513,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2155}
I20260812 06:17:24.641639 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=5.165500
I20260812 06:17:24.661085 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6933336,"delete_count":0,"lbm_write_time_us":7860,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:17:24.661725 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:24.877749 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.216s	user 0.143s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":389,"lbm_read_time_us":15808,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37032,"lbm_writes_lt_1ms":643,"mutex_wait_us":97,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":3000}
I20260812 06:17:24.881122 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=17.071750
I20260812 06:17:24.961403 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.080s	user 0.042s	sys 0.016s Metrics: {"bytes_written":18871349,"delete_count":0,"lbm_write_time_us":26963,"lbm_writes_lt_1ms":463,"reinsert_count":0,"update_count":2300}
I20260812 06:17:24.961987 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=4.173312
I20260812 06:17:24.979910 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":5743636,"delete_count":0,"lbm_write_time_us":7557,"lbm_writes_lt_1ms":143,"reinsert_count":0,"update_count":700}
I20260812 06:17:24.980485 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:25.188246 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.208s	user 0.148s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":938,"lbm_read_time_us":15117,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33933,"lbm_writes_lt_1ms":643,"mutex_wait_us":369,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:17:25.192035 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=15.087375
I20260812 06:17:25.247776 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.055s	user 0.038s	sys 0.017s Metrics: {"bytes_written":16820188,"delete_count":0,"lbm_write_time_us":24043,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:25.248551 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:25.264114 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.264703 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:25.437762 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.173s	user 0.116s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774721,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":379,"lbm_read_time_us":11276,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30203,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:25.438575 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=14.095187
I20260812 06:17:25.517961 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.079s	user 0.038s	sys 0.038s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":29709,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.518769 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=2.188937
I20260812 06:17:25.537580 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.019s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.538280 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:25.577965 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushMRSOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.040s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":289,"dirs.run_wall_time_us":1893,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1548,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:25.578899 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f): free 124257524 bytes of WAL
I20260812 06:17:25.579242 22040 log_reader.cc:385] T 51ccb77ffac44a2c9a4d8723b92c165f: removed 12 log segments from log reader
I20260812 06:17:25.579331 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000027 (ops 130-134)
I20260812 06:17:25.579423 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000028 (ops 135-139)
I20260812 06:17:25.579481 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000029 (ops 140-144)
I20260812 06:17:25.579561 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000030 (ops 145-148)
I20260812 06:17:25.579610 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000031 (ops 149-153)
I20260812 06:17:25.579653 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000032 (ops 154-158)
I20260812 06:17:25.579697 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000033 (ops 159-163)
I20260812 06:17:25.579741 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000034 (ops 164-168)
I20260812 06:17:25.579789 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000035 (ops 169-173)
I20260812 06:17:25.579833 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000036 (ops 174-178)
I20260812 06:17:25.579876 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000037 (ops 179-183)
I20260812 06:17:25.579918 22040 log.cc:1079] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: Deleting log segment in path: /tmp/dist-test-taskNzl8bg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515434485903-21728-0/minicluster-data/ts-0-root/wals/51ccb77ffac44a2c9a4d8723b92c165f/wal-000000038 (ops 184-188)
I20260812 06:17:25.610555 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: LogGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:25.611056 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f): 473 bytes on disk
I20260812 06:17:25.611660 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: UndoDeltaBlockGCOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.613266 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=5.165500
I20260812 06:17:25.630589 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":6358991,"delete_count":0,"lbm_write_time_us":6906,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:17:25.631122 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:25.641966 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.011s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":3029,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:17:25.642511 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=1.000000
I20260812 06:17:25.814060 21728 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.171s	user 1.936s	sys 0.128s
I20260812 06:17:25.888581 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: MajorDeltaCompactionOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.246s	user 0.172s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979697,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":18429,"lbm_reads_lt_1ms":762,"lbm_write_time_us":39487,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3500}
I20260812 06:17:25.889132 22105 maintenance_manager.cc:419] P 0e7a0e20a8e5488e8ed52b3b53b82bba: Scheduling FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f): perf score=14.095187
I20260812 06:17:25.920465 21728 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.106s	user 0.003s	sys 0.000s
I20260812 06:17:25.921307 21728 tablet_server.cc:179] TabletServer@127.21.56.1:0 shutting down...
I20260812 06:17:25.943688 22040 maintenance_manager.cc:643] P 0e7a0e20a8e5488e8ed52b3b53b82bba: FlushDeltaMemStoresOp(51ccb77ffac44a2c9a4d8723b92c165f) complete. Timing: real 0.054s	user 0.036s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23782,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.944686 21728 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:25.944978 21728 tablet_replica.cc:333] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba: stopping tablet replica
I20260812 06:17:25.945155 21728 raft_consensus.cc:2243] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:25.945370 21728 raft_consensus.cc:2272] T 51ccb77ffac44a2c9a4d8723b92c165f P 0e7a0e20a8e5488e8ed52b3b53b82bba [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:25.949352 21728 tablet_server.cc:196] TabletServer@127.21.56.1:0 shutdown complete.
I20260812 06:17:25.957351 21728 master.cc:562] Master@127.21.56.62:38453 shutting down...
I20260812 06:17:25.961022 21728 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:25.961318 21728 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:25.961424 21728 tablet_replica.cc:333] T 00000000000000000000000000000000 P 38abc30d02b04ebf91ec9c82286eeac8: stopping tablet replica
I20260812 06:17:25.974794 21728 master.cc:584] Master@127.21.56.62:38453 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5629 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11577 ms total)

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