[==========] 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:23.949721 12867 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.144.254:37405
I20260812 06:17:23.950886 12867 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:23.951463 12867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:23.958184 12873 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:23.958374 12867 server_base.cc:1061] running on GCE node
W20260812 06:17:23.958173 12875 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:23.960011 12872 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:23.960534 12867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:23.960628 12867 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:23.960666 12867 hybrid_clock.cc:648] HybridClock initialized: now 1786515443960664 us; error 0 us; skew 500 ppm
I20260812 06:17:23.962745 12867 webserver.cc:533] Webserver started at http://127.12.144.254:44607/ using document root <none> and password file <none>
I20260812 06:17:23.963301 12867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:23.963361 12867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:23.963586 12867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:23.965408 12867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/master-0-root/instance:
uuid: "c76e9aa48bc74e378ac458a5396420b9"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-f7th"
I20260812 06:17:23.970742 12867 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.000s	sys 0.003s
I20260812 06:17:23.973841 12880 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:23.975158 12867 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:17:23.975286 12867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/master-0-root
uuid: "c76e9aa48bc74e378ac458a5396420b9"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-f7th"
I20260812 06:17:23.975401 12867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-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:23.990446 12867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:23.991216 12867 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:23.991391 12867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:23.998978 12867 rpc_server.cc:307] RPC server started. Bound to: 127.12.144.254:37405
I20260812 06:17:23.999009 12933 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.144.254:37405 every 8 connection(s)
I20260812 06:17:24.001533 12934 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:24.007870 12934 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9: Bootstrap starting.
I20260812 06:17:24.010197 12934 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.011242 12934 log.cc:826] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:24.012838 12934 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9: No bootstrap required, opened a new log
I20260812 06:17:24.015694 12934 raft_consensus.cc:359] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c76e9aa48bc74e378ac458a5396420b9" member_type: VOTER }
I20260812 06:17:24.015875 12934 raft_consensus.cc:385] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.015955 12934 raft_consensus.cc:740] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c76e9aa48bc74e378ac458a5396420b9, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.016587 12934 consensus_queue.cc:260] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [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: "c76e9aa48bc74e378ac458a5396420b9" member_type: VOTER }
I20260812 06:17:24.016739 12934 raft_consensus.cc:399] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.016810 12934 raft_consensus.cc:493] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.016932 12934 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.017903 12934 raft_consensus.cc:515] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c76e9aa48bc74e378ac458a5396420b9" member_type: VOTER }
I20260812 06:17:24.018411 12934 leader_election.cc:304] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [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: c76e9aa48bc74e378ac458a5396420b9; no voters: 
I20260812 06:17:24.018807 12934 leader_election.cc:290] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.018911 12937 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.019119 12937 raft_consensus.cc:697] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 1 LEADER]: Becoming Leader. State: Replica: c76e9aa48bc74e378ac458a5396420b9, State: Running, Role: LEADER
I20260812 06:17:24.019505 12937 consensus_queue.cc:237] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [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: "c76e9aa48bc74e378ac458a5396420b9" member_type: VOTER }
I20260812 06:17:24.020047 12934 sys_catalog.cc:565] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:24.021386 12939 sys_catalog.cc:455] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c76e9aa48bc74e378ac458a5396420b9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c76e9aa48bc74e378ac458a5396420b9" member_type: VOTER } }
I20260812 06:17:24.021499 12939 sys_catalog.cc:458] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.021811 12946 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:24.021777 12938 sys_catalog.cc:455] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c76e9aa48bc74e378ac458a5396420b9. Latest consensus state: current_term: 1 leader_uuid: "c76e9aa48bc74e378ac458a5396420b9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c76e9aa48bc74e378ac458a5396420b9" member_type: VOTER } }
I20260812 06:17:24.021908 12938 sys_catalog.cc:458] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.024288 12946 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:24.024593 12867 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:24.028890 12946 catalog_manager.cc:1383] Generated new cluster ID: ab288c0109db47f6a523cf7ef3a0bbec
I20260812 06:17:24.028980 12946 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:24.037741 12946 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:24.038584 12946 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:24.046613 12946 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9: Generated new TSK 0
I20260812 06:17:24.047227 12946 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:24.057610 12867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.060096 12956 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:24.060206 12957 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:24.060213 12959 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:24.060324 12867 server_base.cc:1061] running on GCE node
I20260812 06:17:24.060539 12867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.060585 12867 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:24.060604 12867 hybrid_clock.cc:648] HybridClock initialized: now 1786515444060604 us; error 0 us; skew 500 ppm
I20260812 06:17:24.061494 12867 webserver.cc:533] Webserver started at http://127.12.144.193:33731/ using document root <none> and password file <none>
I20260812 06:17:24.061658 12867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.061712 12867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.061786 12867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.062148 12867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/instance:
uuid: "05dfd1306047433b8fef3af25ac9e4e5"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-f7th"
I20260812 06:17:24.063871 12867 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:24.064939 12964 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:24.065187 12867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:24.065294 12867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root
uuid: "05dfd1306047433b8fef3af25ac9e4e5"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-f7th"
I20260812 06:17:24.065397 12867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-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:24.082789 12867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.083225 12867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.083727 12867 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:24.084581 12867 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:24.084635 12867 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.084690 12867 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:24.084719 12867 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.090916 12867 rpc_server.cc:307] RPC server started. Bound to: 127.12.144.193:35401
I20260812 06:17:24.091895 13027 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.144.193:35401 every 8 connection(s)
I20260812 06:17:24.106010 13028 heartbeater.cc:344] Connected to a master server at 127.12.144.254:37405
I20260812 06:17:24.106331 13028 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:24.106933 13028 heartbeater.cc:507] Master 127.12.144.254:37405 requested a full tablet report, sending...
I20260812 06:17:24.108613 12897 ts_manager.cc:194] Registered new tserver with Master: 05dfd1306047433b8fef3af25ac9e4e5 (127.12.144.193:35401)
I20260812 06:17:24.109320 12867 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017608865s
I20260812 06:17:24.109860 12897 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37262
I20260812 06:17:24.119992 12897 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37272:
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:24.136296 12985 tablet_service.cc:1511] Processing CreateTablet for tablet 2bbb4aea2fae4678aa8030231907270c (DEFAULT_TABLE table=heavy-update-compaction-test [id=3d9e36b962d44c24970ba48ecebcc274]), partition=
I20260812 06:17:24.136729 12985 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2bbb4aea2fae4678aa8030231907270c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.138962 13040 tablet_bootstrap.cc:492] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Bootstrap starting.
I20260812 06:17:24.140267 13040 tablet_bootstrap.cc:654] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.141664 13040 tablet_bootstrap.cc:492] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: No bootstrap required, opened a new log
I20260812 06:17:24.141776 13040 ts_tablet_manager.cc:1403] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:24.142306 13040 raft_consensus.cc:359] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "05dfd1306047433b8fef3af25ac9e4e5" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 35401 } }
I20260812 06:17:24.142488 13040 raft_consensus.cc:385] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.142561 13040 raft_consensus.cc:740] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 05dfd1306047433b8fef3af25ac9e4e5, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.142769 13040 consensus_queue.cc:260] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [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: "05dfd1306047433b8fef3af25ac9e4e5" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 35401 } }
I20260812 06:17:24.142913 13040 raft_consensus.cc:399] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.143039 13040 raft_consensus.cc:493] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.143113 13040 raft_consensus.cc:3060] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.144182 13040 raft_consensus.cc:515] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "05dfd1306047433b8fef3af25ac9e4e5" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 35401 } }
I20260812 06:17:24.144344 13040 leader_election.cc:304] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [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: 05dfd1306047433b8fef3af25ac9e4e5; no voters: 
I20260812 06:17:24.144560 13040 leader_election.cc:290] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.144675 13042 raft_consensus.cc:2804] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.144903 13042 raft_consensus.cc:697] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 1 LEADER]: Becoming Leader. State: Replica: 05dfd1306047433b8fef3af25ac9e4e5, State: Running, Role: LEADER
I20260812 06:17:24.145020 13040 ts_tablet_manager.cc:1434] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:24.145073 13042 consensus_queue.cc:237] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [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: "05dfd1306047433b8fef3af25ac9e4e5" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 35401 } }
I20260812 06:17:24.145206 13028 heartbeater.cc:499] Master 127.12.144.254:37405 was elected leader, sending a full tablet report...
I20260812 06:17:24.147822 12897 catalog_manager.cc:5719] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 05dfd1306047433b8fef3af25ac9e4e5 (127.12.144.193). New cstate: current_term: 1 leader_uuid: "05dfd1306047433b8fef3af25ac9e4e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "05dfd1306047433b8fef3af25ac9e4e5" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 35401 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:24.220258 12867 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.027s	sys 0.004s
I20260812 06:17:24.342810 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushMRSOp(2bbb4aea2fae4678aa8030231907270c): perf score=15.086190
I20260812 06:17:24.512444 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushMRSOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.169s	user 0.116s	sys 0.036s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":2137,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":772,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37824,"lbm_writes_lt_1ms":657,"mutex_wait_us":214,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":108,"threads_started":1,"update_count":1500}
I20260812 06:17:24.513619 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c): 12308959 bytes on disk
I20260812 06:17:24.514331 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.514812 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:24.526552 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2133457,"delete_count":0,"lbm_write_time_us":3208,"lbm_writes_lt_1ms":55,"reinsert_count":0,"update_count":260}
I20260812 06:17:24.527098 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling LogGCOp(2bbb4aea2fae4678aa8030231907270c): free 20290830 bytes of WAL
I20260812 06:17:24.527456 12969 log_reader.cc:385] T 2bbb4aea2fae4678aa8030231907270c: removed 2 log segments from log reader
I20260812 06:17:24.527626 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000001 (ops 1-6)
I20260812 06:17:24.527760 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000002 (ops 7-10)
I20260812 06:17:24.532591 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: LogGCOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:17:24.533031 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:24.541741 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":1969352,"delete_count":0,"lbm_write_time_us":2868,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:17:24.542332 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:24.685036 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.142s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631336,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":410,"lbm_read_time_us":8196,"lbm_reads_lt_1ms":469,"lbm_write_time_us":23312,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":255,"threads_started":5,"update_count":2000}
I20260812 06:17:24.685739 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:24.726962 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.041s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18230,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.727412 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:24.742848 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.743337 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:24.881892 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.138s	user 0.110s	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":789,"lbm_read_time_us":8635,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27119,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:17:24.882349 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:24.919974 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.037s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14719,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.920491 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:24.933524 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.933945 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:25.060671 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.127s	user 0.097s	sys 0.029s 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":794,"lbm_read_time_us":8629,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23359,"lbm_writes_lt_1ms":443,"mutex_wait_us":291,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:17:25.061110 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:25.108883 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.048s	user 0.005s	sys 0.030s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14179,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.109470 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:25.125134 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.125716 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:25.277791 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.152s	user 0.115s	sys 0.028s 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":425,"lbm_read_time_us":11404,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22632,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.278263 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:25.330714 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.052s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17005,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.331292 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:25.348137 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.348667 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:25.481213 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.132s	user 0.110s	sys 0.008s 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":523,"lbm_read_time_us":9818,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19809,"lbm_writes_lt_1ms":443,"mutex_wait_us":239,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.481767 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:25.535108 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.053s	user 0.014s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18042,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:17:25.535566 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:25.545467 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.545872 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:25.661725 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.116s	user 0.095s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":403,"lbm_read_time_us":8454,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21962,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":33152,"update_count":2000}
I20260812 06:17:25.662268 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=7.149875
I20260812 06:17:25.695153 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.033s	user 0.021s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12209,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:25.695660 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:25.710891 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3507,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.711436 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:25.867197 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.156s	user 0.082s	sys 0.059s 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":802,"lbm_read_time_us":9307,"lbm_reads_lt_1ms":372,"lbm_write_time_us":22320,"lbm_writes_lt_1ms":343,"mutex_wait_us":299,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1500}
I20260812 06:17:25.867904 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:25.909766 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.042s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14874,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.910326 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:25.920147 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.920619 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushMRSOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:25.956583 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushMRSOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.036s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1273,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1389,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:25.957545 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling LogGCOp(2bbb4aea2fae4678aa8030231907270c): free 117302582 bytes of WAL
I20260812 06:17:25.957871 12969 log_reader.cc:385] T 2bbb4aea2fae4678aa8030231907270c: removed 12 log segments from log reader
I20260812 06:17:25.957927 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000003 (ops 11-15)
I20260812 06:17:25.957964 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000004 (ops 16-20)
I20260812 06:17:25.957993 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000005 (ops 21-24)
I20260812 06:17:25.958022 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000006 (ops 25-29)
I20260812 06:17:25.958050 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000007 (ops 30-34)
I20260812 06:17:25.958084 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000008 (ops 35-39)
I20260812 06:17:25.958114 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000009 (ops 40-44)
I20260812 06:17:25.958142 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000010 (ops 45-49)
I20260812 06:17:25.958175 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000011 (ops 50-54)
I20260812 06:17:25.958205 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000012 (ops 55-58)
I20260812 06:17:25.958237 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000013 (ops 59-63)
I20260812 06:17:25.958269 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000014 (ops 64-68)
I20260812 06:17:25.977564 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: LogGCOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.020s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:25.978003 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c): 482 bytes on disk
I20260812 06:17:25.978564 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.979157 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:26.005036 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.026s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.005530 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:26.021005 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.021565 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:26.209955 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.188s	user 0.139s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836375,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":137,"lbm_read_time_us":11362,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33474,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:17:26.210390 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=14.095187
I20260812 06:17:26.264571 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.054s	user 0.014s	sys 0.039s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24329,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.264986 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:26.275434 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3610,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.275966 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:26.441047 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.165s	user 0.130s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":11716,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31130,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:17:26.441648 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=11.118625
I20260812 06:17:26.474061 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.032s	user 0.024s	sys 0.005s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13233,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:26.474696 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:26.488240 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4819,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.488673 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:26.615715 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.127s	user 0.100s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":9867,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20966,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:17:26.619903 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:26.649549 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.029s	user 0.006s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12644,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.650041 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:26.754268 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.103s	user 0.058s	sys 0.036s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1028,"lbm_read_time_us":6932,"lbm_reads_lt_1ms":367,"lbm_write_time_us":16284,"lbm_writes_lt_1ms":343,"mutex_wait_us":299,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.754773 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:26.805310 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.050s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15915,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.805852 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:26.820789 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.821266 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:26.938691 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.117s	user 0.103s	sys 0.013s 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":520,"lbm_read_time_us":9710,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20396,"lbm_writes_lt_1ms":443,"mutex_wait_us":251,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:26.939152 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=7.149875
I20260812 06:17:26.966320 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.027s	user 0.018s	sys 0.006s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9483,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:26.966948 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:26.985736 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6487,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.986305 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:27.100112 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.114s	user 0.100s	sys 0.011s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":532,"lbm_read_time_us":6454,"lbm_reads_lt_1ms":364,"lbm_write_time_us":19682,"lbm_writes_lt_1ms":343,"mutex_wait_us":69,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.103508 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=11.118625
I20260812 06:17:27.139302 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.036s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":15524,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:17:27.139889 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:27.153920 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:27.154378 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:27.306989 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.152s	user 0.091s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631308,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":441,"lbm_read_time_us":10932,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27090,"lbm_writes_lt_1ms":443,"mutex_wait_us":519,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:17:27.308962 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:27.350835 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.041s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17485,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.351329 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:27.362171 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.362705 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushMRSOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:27.401856 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushMRSOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.039s	user 0.028s	sys 0.009s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1219,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1465,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:27.402860 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling LogGCOp(2bbb4aea2fae4678aa8030231907270c): free 124710308 bytes of WAL
I20260812 06:17:27.403105 12969 log_reader.cc:385] T 2bbb4aea2fae4678aa8030231907270c: removed 12 log segments from log reader
I20260812 06:17:27.403156 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000015 (ops 69-73)
I20260812 06:17:27.403200 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000016 (ops 74-78)
I20260812 06:17:27.403230 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000017 (ops 79-83)
I20260812 06:17:27.403251 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000018 (ops 84-88)
I20260812 06:17:27.403277 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000019 (ops 89-93)
I20260812 06:17:27.403304 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000020 (ops 94-98)
I20260812 06:17:27.403331 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000021 (ops 99-103)
I20260812 06:17:27.403358 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000022 (ops 104-108)
I20260812 06:17:27.403379 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000023 (ops 109-113)
I20260812 06:17:27.403404 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000024 (ops 114-118)
I20260812 06:17:27.403430 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000025 (ops 119-123)
I20260812 06:17:27.403451 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000026 (ops 124-128)
I20260812 06:17:27.429626 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: LogGCOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:27.430051 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c): 462 bytes on disk
I20260812 06:17:27.430552 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c) 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:27.431152 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:27.446638 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.447909 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:27.598577 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.150s	user 0.094s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733844,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":297,"lbm_read_time_us":9705,"lbm_reads_lt_1ms":569,"lbm_write_time_us":24875,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":73,"threads_started":1,"update_count":2500}
I20260812 06:17:27.599073 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:27.641090 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.042s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16496,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.641696 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:27.657385 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5823,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.657943 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:27.789281 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.131s	user 0.098s	sys 0.031s 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":89,"lbm_read_time_us":10375,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21460,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:17:27.789781 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:27.842267 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.052s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19889,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.842756 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:27.857889 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.858526 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:27.989290 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.131s	user 0.098s	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":133,"lbm_read_time_us":9891,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21923,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.989777 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:28.038961 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.049s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17248,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.039496 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:28.054448 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.054962 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:28.192749 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.138s	user 0.114s	sys 0.012s 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":4894,"lbm_read_time_us":9205,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23182,"lbm_writes_lt_1ms":443,"mutex_wait_us":4045,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:17:28.193662 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:28.249878 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.056s	user 0.017s	sys 0.034s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19504,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.250432 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:28.266165 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.266738 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:28.425671 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.159s	user 0.118s	sys 0.038s 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":790,"lbm_read_time_us":11605,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27707,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":218,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.426134 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:28.476433 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.050s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18483,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.476977 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:28.492264 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.492806 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:28.626721 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.134s	user 0.094s	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":969,"lbm_read_time_us":9614,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21637,"lbm_writes_lt_1ms":443,"mutex_wait_us":724,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32000,"update_count":2000}
I20260812 06:17:28.627265 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:28.674899 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.047s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17405,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.675529 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:28.689769 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.690373 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:28.824292 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.134s	user 0.109s	sys 0.019s 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":163,"lbm_read_time_us":9196,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24904,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.824831 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=10.126437
I20260812 06:17:28.881739 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.057s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17523,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.882285 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:28.893777 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.894375 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushMRSOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:28.940977 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushMRSOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.046s	user 0.029s	sys 0.002s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1282,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1343,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:28.941674 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling LogGCOp(2bbb4aea2fae4678aa8030231907270c): free 115943417 bytes of WAL
I20260812 06:17:28.941892 12969 log_reader.cc:385] T 2bbb4aea2fae4678aa8030231907270c: removed 11 log segments from log reader
I20260812 06:17:28.941975 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000027 (ops 129-133)
I20260812 06:17:28.942029 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000028 (ops 134-138)
I20260812 06:17:28.942063 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000029 (ops 139-143)
I20260812 06:17:28.942095 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000030 (ops 144-148)
I20260812 06:17:28.942127 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000031 (ops 149-153)
I20260812 06:17:28.942158 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000032 (ops 154-158)
I20260812 06:17:28.942188 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000033 (ops 159-163)
I20260812 06:17:28.942217 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000034 (ops 164-168)
I20260812 06:17:28.942247 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000035 (ops 169-173)
I20260812 06:17:28.942276 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000036 (ops 174-178)
I20260812 06:17:28.942306 12969 log.cc:1079] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/2bbb4aea2fae4678aa8030231907270c/wal-000000037 (ops 179-183)
I20260812 06:17:28.966454 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: LogGCOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:28.966859 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=3.181125
I20260812 06:17:28.990414 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5565,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:28.990851 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:29.002208 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.002611 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:29.220984 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.218s	user 0.130s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":6949,"dirs.run_cpu_time_us":491,"dirs.run_wall_time_us":3408,"lbm_read_time_us":16028,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33690,"lbm_writes_lt_1ms":643,"mutex_wait_us":3486,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:29.221817 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c): 462 bytes on disk
I20260812 06:17:29.222357 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: UndoDeltaBlockGCOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.223002 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=14.095187
I20260812 06:17:29.284530 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.061s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21981,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.285187 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c): perf score=2.188937
I20260812 06:17:29.300463 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: FlushDeltaMemStoresOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.300959 13029 maintenance_manager.cc:419] P 05dfd1306047433b8fef3af25ac9e4e5: Scheduling MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c): perf score=1.000000
I20260812 06:17:29.345989 12867 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.126s	user 1.837s	sys 0.117s
I20260812 06:17:29.434182 12867 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.088s	user 0.000s	sys 0.003s
I20260812 06:17:29.434895 12867 tablet_server.cc:179] TabletServer@127.12.144.193:0 shutting down...
I20260812 06:17:29.474133 12969 maintenance_manager.cc:643] P 05dfd1306047433b8fef3af25ac9e4e5: MajorDeltaCompactionOp(2bbb4aea2fae4678aa8030231907270c) complete. Timing: real 0.173s	user 0.122s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":989,"lbm_read_time_us":11718,"lbm_reads_lt_1ms":568,"lbm_write_time_us":35924,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31488,"update_count":2500}
I20260812 06:17:29.474812 12867 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:29.475317 12867 tablet_replica.cc:333] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5: stopping tablet replica
I20260812 06:17:29.475621 12867 raft_consensus.cc:2243] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.475878 12867 raft_consensus.cc:2272] T 2bbb4aea2fae4678aa8030231907270c P 05dfd1306047433b8fef3af25ac9e4e5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.495402 12867 tablet_server.cc:196] TabletServer@127.12.144.193:0 shutdown complete.
I20260812 06:17:29.520965 12867 master.cc:562] Master@127.12.144.254:37405 shutting down...
I20260812 06:17:29.529448 12867 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.529639 12867 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.529731 12867 tablet_replica.cc:333] T 00000000000000000000000000000000 P c76e9aa48bc74e378ac458a5396420b9: stopping tablet replica
I20260812 06:17:29.542285 12867 master.cc:584] Master@127.12.144.254:37405 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5665 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:29.623832 12867 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.144.254:36131
I20260812 06:17:29.624318 12867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:29.626798 13064 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:29.626927 12867 server_base.cc:1061] running on GCE node
W20260812 06:17:29.626971 13061 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:29.626837 13062 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:29.627281 12867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.627323 12867 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:29.627337 12867 hybrid_clock.cc:648] HybridClock initialized: now 1786515449627337 us; error 0 us; skew 500 ppm
I20260812 06:17:29.628147 12867 webserver.cc:533] Webserver started at http://127.12.144.254:38513/ using document root <none> and password file <none>
I20260812 06:17:29.628296 12867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.628340 12867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.628413 12867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.628789 12867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/master-0-root/instance:
uuid: "cb7aff111dc94457afab901042da6ea7"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-f7th"
I20260812 06:17:29.630195 12867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:29.631054 13069 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:29.631274 12867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.631342 12867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/master-0-root
uuid: "cb7aff111dc94457afab901042da6ea7"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-f7th"
I20260812 06:17:29.631410 12867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-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:29.640062 12867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.640491 12867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.644680 12867 rpc_server.cc:307] RPC server started. Bound to: 127.12.144.254:36131
I20260812 06:17:29.648484 13121 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.144.254:36131 every 8 connection(s)
I20260812 06:17:29.649104 13122 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:29.651489 13122 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7: Bootstrap starting.
I20260812 06:17:29.652305 13122 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.653299 13122 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7: No bootstrap required, opened a new log
I20260812 06:17:29.653688 13122 raft_consensus.cc:359] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb7aff111dc94457afab901042da6ea7" member_type: VOTER }
I20260812 06:17:29.653777 13122 raft_consensus.cc:385] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.653806 13122 raft_consensus.cc:740] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cb7aff111dc94457afab901042da6ea7, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.653941 13122 consensus_queue.cc:260] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [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: "cb7aff111dc94457afab901042da6ea7" member_type: VOTER }
I20260812 06:17:29.654032 13122 raft_consensus.cc:399] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.654071 13122 raft_consensus.cc:493] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.654125 13122 raft_consensus.cc:3060] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.655097 13122 raft_consensus.cc:515] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb7aff111dc94457afab901042da6ea7" member_type: VOTER }
I20260812 06:17:29.655233 13122 leader_election.cc:304] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [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: cb7aff111dc94457afab901042da6ea7; no voters: 
I20260812 06:17:29.655431 13122 leader_election.cc:290] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.655573 13125 raft_consensus.cc:2804] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.655791 13125 raft_consensus.cc:697] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 1 LEADER]: Becoming Leader. State: Replica: cb7aff111dc94457afab901042da6ea7, State: Running, Role: LEADER
I20260812 06:17:29.655925 13125 consensus_queue.cc:237] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [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: "cb7aff111dc94457afab901042da6ea7" member_type: VOTER }
I20260812 06:17:29.655994 13122 sys_catalog.cc:565] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:29.656332 13127 sys_catalog.cc:455] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader cb7aff111dc94457afab901042da6ea7. Latest consensus state: current_term: 1 leader_uuid: "cb7aff111dc94457afab901042da6ea7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb7aff111dc94457afab901042da6ea7" member_type: VOTER } }
I20260812 06:17:29.656322 13126 sys_catalog.cc:455] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "cb7aff111dc94457afab901042da6ea7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb7aff111dc94457afab901042da6ea7" member_type: VOTER } }
I20260812 06:17:29.656452 13127 sys_catalog.cc:458] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.656466 13126 sys_catalog.cc:458] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.656737 13129 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:29.657604 13129 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:29.657889 12867 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:29.659727 13129 catalog_manager.cc:1383] Generated new cluster ID: 700e53fc24d04405831c4ab2fb8f116c
I20260812 06:17:29.659782 13129 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:29.683171 13129 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:29.684032 13129 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:29.694909 13129 catalog_manager.cc:6092] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7: Generated new TSK 0
I20260812 06:17:29.695108 13129 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:29.722491 12867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:29.724695 13143 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:29.724754 13146 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:29.724804 13144 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:29.724996 12867 server_base.cc:1061] running on GCE node
I20260812 06:17:29.725224 12867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.725276 12867 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:29.725291 12867 hybrid_clock.cc:648] HybridClock initialized: now 1786515449725291 us; error 0 us; skew 500 ppm
I20260812 06:17:29.726066 12867 webserver.cc:533] Webserver started at http://127.12.144.193:46845/ using document root <none> and password file <none>
I20260812 06:17:29.726220 12867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.726270 12867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.726343 12867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.726743 12867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/instance:
uuid: "cc1fd5b2610d4fc29b198a8643204cef"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-f7th"
I20260812 06:17:29.728236 12867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:29.729179 13151 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:29.729425 12867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:29.729489 12867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root
uuid: "cc1fd5b2610d4fc29b198a8643204cef"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-f7th"
I20260812 06:17:29.729566 12867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-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:29.744493 12867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.744879 12867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.745155 12867 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:29.745596 12867 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:29.745648 12867 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.745702 12867 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:29.745728 12867 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.750191 12867 rpc_server.cc:307] RPC server started. Bound to: 127.12.144.193:43229
I20260812 06:17:29.750478 13214 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.144.193:43229 every 8 connection(s)
I20260812 06:17:29.759625 13215 heartbeater.cc:344] Connected to a master server at 127.12.144.254:36131
I20260812 06:17:29.759732 13215 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:29.759958 13215 heartbeater.cc:507] Master 127.12.144.254:36131 requested a full tablet report, sending...
I20260812 06:17:29.760568 13086 ts_manager.cc:194] Registered new tserver with Master: cc1fd5b2610d4fc29b198a8643204cef (127.12.144.193:43229)
I20260812 06:17:29.760685 12867 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009974212s
I20260812 06:17:29.761312 13086 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38110
I20260812 06:17:29.768291 13086 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38116:
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:29.778800 13176 tablet_service.cc:1511] Processing CreateTablet for tablet 9a504e4c63f645ccbe0eadf854282762 (DEFAULT_TABLE table=heavy-update-compaction-test [id=451c95b8daea48f0842be74c1aea4503]), partition=
I20260812 06:17:29.779042 13176 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9a504e4c63f645ccbe0eadf854282762. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:29.781178 13227 tablet_bootstrap.cc:492] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Bootstrap starting.
I20260812 06:17:29.782146 13227 tablet_bootstrap.cc:654] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.783219 13227 tablet_bootstrap.cc:492] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: No bootstrap required, opened a new log
I20260812 06:17:29.783298 13227 ts_tablet_manager.cc:1403] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:29.783890 13227 raft_consensus.cc:359] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc1fd5b2610d4fc29b198a8643204cef" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 43229 } }
I20260812 06:17:29.783984 13227 raft_consensus.cc:385] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.784006 13227 raft_consensus.cc:740] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cc1fd5b2610d4fc29b198a8643204cef, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.784117 13227 consensus_queue.cc:260] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [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: "cc1fd5b2610d4fc29b198a8643204cef" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 43229 } }
I20260812 06:17:29.784193 13227 raft_consensus.cc:399] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.784221 13227 raft_consensus.cc:493] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.784255 13227 raft_consensus.cc:3060] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.784911 13227 raft_consensus.cc:515] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc1fd5b2610d4fc29b198a8643204cef" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 43229 } }
I20260812 06:17:29.785027 13227 leader_election.cc:304] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [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: cc1fd5b2610d4fc29b198a8643204cef; no voters: 
I20260812 06:17:29.785204 13227 leader_election.cc:290] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.785342 13229 raft_consensus.cc:2804] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.785478 13227 ts_tablet_manager.cc:1434] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:29.785543 13215 heartbeater.cc:499] Master 127.12.144.254:36131 was elected leader, sending a full tablet report...
I20260812 06:17:29.785589 13229 raft_consensus.cc:697] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 1 LEADER]: Becoming Leader. State: Replica: cc1fd5b2610d4fc29b198a8643204cef, State: Running, Role: LEADER
I20260812 06:17:29.785707 13229 consensus_queue.cc:237] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [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: "cc1fd5b2610d4fc29b198a8643204cef" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 43229 } }
I20260812 06:17:29.787058 13086 catalog_manager.cc:5719] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef reported cstate change: term changed from 0 to 1, leader changed from <none> to cc1fd5b2610d4fc29b198a8643204cef (127.12.144.193). New cstate: current_term: 1 leader_uuid: "cc1fd5b2610d4fc29b198a8643204cef" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc1fd5b2610d4fc29b198a8643204cef" member_type: VOTER last_known_addr { host: "127.12.144.193" port: 43229 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:29.851965 12867 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.014s	sys 0.008s
I20260812 06:17:30.001387 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushMRSOp(9a504e4c63f645ccbe0eadf854282762): perf score=19.054940
I20260812 06:17:30.195833 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushMRSOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.194s	user 0.122s	sys 0.061s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":129,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":991,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45324,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:30.196589 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling LogGCOp(9a504e4c63f645ccbe0eadf854282762): free 20743880 bytes of WAL
I20260812 06:17:30.196825 13156 log_reader.cc:385] T 9a504e4c63f645ccbe0eadf854282762: removed 2 log segments from log reader
I20260812 06:17:30.196888 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000001 (ops 1-6)
I20260812 06:17:30.196982 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000002 (ops 7-11)
I20260812 06:17:30.201732 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: LogGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:30.202077 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762): 16411392 bytes on disk
I20260812 06:17:30.202539 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762) 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:30.202920 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:30.217563 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5497,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.218124 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:30.380760 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.162s	user 0.096s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":493,"lbm_read_time_us":11266,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23189,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":297,"threads_started":5,"update_count":2000}
I20260812 06:17:30.381589 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:30.432050 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.050s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17545,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.432557 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:30.447707 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.448235 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:30.593187 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.145s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":8837,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23281,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:17:30.593765 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:30.642634 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.049s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15803,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.643133 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:30.657691 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.658325 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:30.795928 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.137s	user 0.108s	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,"lbm_read_time_us":9344,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25308,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.796355 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=11.118625
I20260812 06:17:30.839982 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.043s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15760,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:30.840521 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:30.854139 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4678,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.854715 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:30.987109 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.132s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":875,"lbm_read_time_us":10561,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20710,"lbm_writes_lt_1ms":443,"mutex_wait_us":290,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:17:30.987665 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:31.047377 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.060s	user 0.013s	sys 0.035s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18977,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.047906 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:31.063097 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.063633 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:31.229432 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.166s	user 0.106s	sys 0.051s 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":462,"lbm_read_time_us":11591,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25395,"lbm_writes_lt_1ms":443,"mutex_wait_us":267,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:31.230012 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:31.277972 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.048s	user 0.024s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15471,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.278491 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:31.293721 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.294241 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:31.429046 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.135s	user 0.091s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":584,"lbm_read_time_us":9506,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19883,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:17:31.429594 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:31.477982 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.048s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18067,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.478432 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:31.488262 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.488674 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushMRSOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:31.520992 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushMRSOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.032s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1048,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1237,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:31.521610 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling LogGCOp(9a504e4c63f645ccbe0eadf854282762): free 112239310 bytes of WAL
I20260812 06:17:31.521795 13156 log_reader.cc:385] T 9a504e4c63f645ccbe0eadf854282762: removed 11 log segments from log reader
I20260812 06:17:31.521836 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000003 (ops 12-16)
I20260812 06:17:31.521875 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000004 (ops 17-21)
I20260812 06:17:31.521914 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000005 (ops 22-26)
I20260812 06:17:31.521939 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000006 (ops 27-30)
I20260812 06:17:31.521968 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000007 (ops 31-35)
I20260812 06:17:31.521996 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000008 (ops 36-40)
I20260812 06:17:31.522027 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000009 (ops 41-45)
I20260812 06:17:31.522058 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000010 (ops 46-50)
I20260812 06:17:31.522092 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000011 (ops 51-55)
I20260812 06:17:31.522125 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000012 (ops 56-60)
I20260812 06:17:31.522158 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000013 (ops 61-65)
I20260812 06:17:31.540520 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: LogGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.019s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:31.540930 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762): 447 bytes on disk
I20260812 06:17:31.541376 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:31.541932 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:31.570495 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.028s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.570935 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:31.585362 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.586026 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:31.769049 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.183s	user 0.130s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":292,"lbm_read_time_us":13364,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31004,"lbm_writes_lt_1ms":643,"mutex_wait_us":271,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":26112,"thread_start_us":67,"threads_started":1,"update_count":3000}
I20260812 06:17:31.771906 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=14.095187
I20260812 06:17:31.825577 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.053s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25230,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.826267 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:31.840926 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5037,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.841403 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:31.996529 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.155s	user 0.123s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":10286,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28899,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:31.997247 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=14.095187
I20260812 06:17:32.054611 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.057s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22476,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.055279 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:32.071731 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.072160 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:32.220494 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.148s	user 0.100s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":8472,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25153,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:32.221134 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=11.118625
I20260812 06:17:32.257310 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15674,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:32.257982 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:32.270419 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4614,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.270943 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:32.400919 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.130s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":539,"lbm_read_time_us":9605,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19474,"lbm_writes_lt_1ms":443,"mutex_wait_us":236,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:17:32.401461 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:32.446162 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.045s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15901,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.446583 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:32.456529 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.456936 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:32.598924 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.142s	user 0.112s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":8556,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26278,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:17:32.599421 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:32.632090 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.033s	user 0.026s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11602,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.632669 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:32.748100 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.115s	user 0.080s	sys 0.027s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":114,"lbm_read_time_us":6689,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17874,"lbm_writes_lt_1ms":343,"mutex_wait_us":59,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:17:32.748736 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:32.790726 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.042s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17385,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.791253 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:32.916177 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.125s	user 0.089s	sys 0.031s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":423,"lbm_read_time_us":9334,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17817,"lbm_writes_lt_1ms":343,"mutex_wait_us":347,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":1500}
I20260812 06:17:32.916751 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:32.965936 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.049s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17992,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.966481 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:32.981346 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.981950 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushMRSOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:33.012756 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushMRSOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.030s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":167,"dirs.run_wall_time_us":1433,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1396,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:33.013442 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling LogGCOp(9a504e4c63f645ccbe0eadf854282762): free 121006437 bytes of WAL
I20260812 06:17:33.013670 13156 log_reader.cc:385] T 9a504e4c63f645ccbe0eadf854282762: removed 12 log segments from log reader
I20260812 06:17:33.013716 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000014 (ops 66-70)
I20260812 06:17:33.013756 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000015 (ops 71-75)
I20260812 06:17:33.013819 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000016 (ops 76-80)
I20260812 06:17:33.013856 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000017 (ops 81-85)
I20260812 06:17:33.013882 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000018 (ops 86-90)
I20260812 06:17:33.013939 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000019 (ops 91-95)
I20260812 06:17:33.013975 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000020 (ops 96-100)
I20260812 06:17:33.014000 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000021 (ops 101-105)
I20260812 06:17:33.014050 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000022 (ops 106-110)
I20260812 06:17:33.014086 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000023 (ops 111-114)
I20260812 06:17:33.014137 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000024 (ops 115-119)
I20260812 06:17:33.014171 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000025 (ops 120-124)
I20260812 06:17:33.035435 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: LogGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.022s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:17:33.035905 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762): 472 bytes on disk
I20260812 06:17:33.036329 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.037041 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=3.181125
I20260812 06:17:33.058328 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.021s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:33.058775 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling LogGCOp(9a504e4c63f645ccbe0eadf854282762): free 11564877 bytes of WAL
I20260812 06:17:33.059795 13156 log_reader.cc:385] T 9a504e4c63f645ccbe0eadf854282762: removed 1 log segments from log reader
I20260812 06:17:33.059899 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000026 (ops 125-128)
I20260812 06:17:33.062355 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: LogGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.003s	user 0.001s	sys 0.001s Metrics: {}
I20260812 06:17:33.062655 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:33.076905 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5252,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.077555 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:33.297752 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.220s	user 0.148s	sys 0.058s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":992,"lbm_read_time_us":12773,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35806,"lbm_writes_lt_1ms":643,"mutex_wait_us":263,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:33.298288 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=18.063937
I20260812 06:17:33.371409 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.073s	user 0.046s	sys 0.023s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28203,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:33.372038 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:33.386957 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5521,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.387441 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:33.573107 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.185s	user 0.125s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":44,"lbm_read_time_us":15669,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29719,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:17:33.573737 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:33.609686 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.036s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14326,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.610200 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:33.630947 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.021s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.631374 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:33.790915 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.159s	user 0.100s	sys 0.060s 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":69,"lbm_read_time_us":9828,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24611,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:17:33.791460 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:33.834631 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.043s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14560,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.835115 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:33.845085 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.845491 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:33.974644 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.129s	user 0.092s	sys 0.035s 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":269,"lbm_read_time_us":9400,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":23540,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:17:33.975227 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:34.022642 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.047s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17215,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.023202 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:34.038434 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.039047 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:34.172245 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.132s	user 0.103s	sys 0.028s 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":463,"lbm_read_time_us":8826,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24084,"lbm_writes_lt_1ms":443,"mutex_wait_us":264,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:17:34.172865 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:34.230484 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.057s	user 0.025s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20064,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.231086 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:34.245879 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5543,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.246381 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:34.399477 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.153s	user 0.098s	sys 0.052s 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":1108,"lbm_read_time_us":11071,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24206,"lbm_writes_lt_1ms":443,"mutex_wait_us":522,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:34.400032 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:34.444222 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.044s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14319,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.444734 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:34.457443 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.458058 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushMRSOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:34.490907 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushMRSOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1332,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1672,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:34.491698 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling LogGCOp(9a504e4c63f645ccbe0eadf854282762): free 112692608 bytes of WAL
I20260812 06:17:34.491900 13156 log_reader.cc:385] T 9a504e4c63f645ccbe0eadf854282762: removed 11 log segments from log reader
I20260812 06:17:34.491950 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000027 (ops 129-133)
I20260812 06:17:34.492038 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000028 (ops 134-138)
I20260812 06:17:34.492074 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000029 (ops 139-143)
I20260812 06:17:34.492096 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000030 (ops 144-148)
I20260812 06:17:34.492151 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000031 (ops 149-153)
I20260812 06:17:34.492183 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000032 (ops 154-158)
I20260812 06:17:34.492236 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000033 (ops 159-163)
I20260812 06:17:34.492269 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000034 (ops 164-169)
I20260812 06:17:34.492321 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000035 (ops 170-174)
I20260812 06:17:34.492354 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000036 (ops 175-178)
I20260812 06:17:34.492376 13156 log.cc:1079] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: Deleting log segment in path: /tmp/dist-test-taskAkVpyc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443938153-12867-0/minicluster-data/ts-0-root/wals/9a504e4c63f645ccbe0eadf854282762/wal-000000037 (ops 179-183)
I20260812 06:17:34.515884 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: LogGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:34.516323 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=3.181125
I20260812 06:17:34.544116 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.028s	user 0.016s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6542,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:34.544548 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762): 447 bytes on disk
I20260812 06:17:34.544929 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: UndoDeltaBlockGCOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.545408 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:34.555027 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3500,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.555387 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:34.771322 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.216s	user 0.160s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2297,"lbm_read_time_us":14469,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32803,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:17:34.772076 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=14.095187
I20260812 06:17:34.829936 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.058s	user 0.025s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21797,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.830444 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=2.188937
I20260812 06:17:34.843271 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.843845 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:34.998416 12867 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.146s	user 1.879s	sys 0.166s
I20260812 06:17:35.022305 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.178s	user 0.132s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":12565,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31318,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:35.022818 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762): perf score=10.126437
I20260812 06:17:35.064179 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: FlushDeltaMemStoresOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.041s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17228,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.064765 13216 maintenance_manager.cc:419] P cc1fd5b2610d4fc29b198a8643204cef: Scheduling MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762): perf score=1.000000
I20260812 06:17:35.077994 12867 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.004s	sys 0.000s
I20260812 06:17:35.078660 12867 tablet_server.cc:179] TabletServer@127.12.144.193:0 shutting down...
I20260812 06:17:35.165395 13156 maintenance_manager.cc:643] P cc1fd5b2610d4fc29b198a8643204cef: MajorDeltaCompactionOp(9a504e4c63f645ccbe0eadf854282762) complete. Timing: real 0.100s	user 0.075s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":236,"lbm_read_time_us":7908,"lbm_reads_lt_1ms":367,"lbm_write_time_us":19487,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":67,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.166337 12867 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:35.166704 12867 tablet_replica.cc:333] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef: stopping tablet replica
I20260812 06:17:35.166832 12867 raft_consensus.cc:2243] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.166988 12867 raft_consensus.cc:2272] T 9a504e4c63f645ccbe0eadf854282762 P cc1fd5b2610d4fc29b198a8643204cef [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.171116 12867 tablet_server.cc:196] TabletServer@127.12.144.193:0 shutdown complete.
I20260812 06:17:35.201614 12867 master.cc:562] Master@127.12.144.254:36131 shutting down...
I20260812 06:17:35.205575 12867 raft_consensus.cc:2243] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.205767 12867 raft_consensus.cc:2272] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.205833 12867 tablet_replica.cc:333] T 00000000000000000000000000000000 P cb7aff111dc94457afab901042da6ea7: stopping tablet replica
I20260812 06:17:35.218076 12867 master.cc:584] Master@127.12.144.254:36131 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5678 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11345 ms total)

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