[==========] 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:16:45.938366 28006 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.89.190:41377
I20260812 06:16:45.939888 28006 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:16:45.940758 28006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:45.950474 28006 server_base.cc:1061] running on GCE node
W20260812 06:16:45.950455 28019 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:16:45.950726 28015 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:16:45.950762 28021 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:16:45.951685 28006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:45.951813 28006 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:16:45.951879 28006 hybrid_clock.cc:648] HybridClock initialized: now 1786515405951874 us; error 0 us; skew 500 ppm
I20260812 06:16:45.954303 28006 webserver.cc:533] Webserver started at http://127.27.89.190:38005/ using document root <none> and password file <none>
I20260812 06:16:45.955119 28006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:45.955200 28006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:45.955523 28006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:45.957695 28006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/master-0-root/instance:
uuid: "97618ac8903a4d438e8145925a85782d"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-h3ft"
I20260812 06:16:45.962504 28006 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.006s	sys 0.001s
I20260812 06:16:45.965616 28028 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:16:45.967248 28006 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:45.967413 28006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/master-0-root
uuid: "97618ac8903a4d438e8145925a85782d"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-h3ft"
I20260812 06:16:45.967561 28006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-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:16:45.984405 28006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:45.985285 28006 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:16:45.985507 28006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:45.996080 28006 rpc_server.cc:307] RPC server started. Bound to: 127.27.89.190:41377
I20260812 06:16:45.996104 28119 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.89.190:41377 every 8 connection(s)
I20260812 06:16:45.999600 28120 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:16:46.006831 28120 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d: Bootstrap starting.
I20260812 06:16:46.010072 28120 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.011453 28120 log.cc:826] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:46.014446 28120 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d: No bootstrap required, opened a new log
I20260812 06:16:46.018095 28120 raft_consensus.cc:359] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "97618ac8903a4d438e8145925a85782d" member_type: VOTER }
I20260812 06:16:46.018337 28120 raft_consensus.cc:385] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.018386 28120 raft_consensus.cc:740] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 97618ac8903a4d438e8145925a85782d, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.019294 28120 consensus_queue.cc:260] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [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: "97618ac8903a4d438e8145925a85782d" member_type: VOTER }
I20260812 06:16:46.019486 28120 raft_consensus.cc:399] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.019605 28120 raft_consensus.cc:493] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.019809 28120 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.020857 28120 raft_consensus.cc:515] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "97618ac8903a4d438e8145925a85782d" member_type: VOTER }
I20260812 06:16:46.021440 28120 leader_election.cc:304] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [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: 97618ac8903a4d438e8145925a85782d; no voters: 
I20260812 06:16:46.021975 28120 leader_election.cc:290] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.022320 28128 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.022761 28128 raft_consensus.cc:697] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 1 LEADER]: Becoming Leader. State: Replica: 97618ac8903a4d438e8145925a85782d, State: Running, Role: LEADER
I20260812 06:16:46.023412 28120 sys_catalog.cc:565] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:46.023411 28128 consensus_queue.cc:237] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [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: "97618ac8903a4d438e8145925a85782d" member_type: VOTER }
I20260812 06:16:46.026170 28132 sys_catalog.cc:455] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 97618ac8903a4d438e8145925a85782d. Latest consensus state: current_term: 1 leader_uuid: "97618ac8903a4d438e8145925a85782d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "97618ac8903a4d438e8145925a85782d" member_type: VOTER } }
I20260812 06:16:46.026347 28132 sys_catalog.cc:458] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:46.026358 28006 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:46.026153 28131 sys_catalog.cc:455] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "97618ac8903a4d438e8145925a85782d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "97618ac8903a4d438e8145925a85782d" member_type: VOTER } }
I20260812 06:16:46.026681 28131 sys_catalog.cc:458] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [sys.catalog]: This master's current role is: LEADER
W20260812 06:16:46.029325 28153 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:46.029421 28153 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:46.029524 28154 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:46.030467 28154 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:46.037581 28154 catalog_manager.cc:1383] Generated new cluster ID: ae6cdd09cfe34c1b843065cbb871494e
I20260812 06:16:46.037681 28154 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:46.050781 28154 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:46.052431 28154 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:46.071462 28154 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d: Generated new TSK 0
I20260812 06:16:46.072744 28154 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:46.092473 28006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:46.095887 28164 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:16:46.096067 28162 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:16:46.095892 28161 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:16:46.097615 28006 server_base.cc:1061] running on GCE node
I20260812 06:16:46.097951 28006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:46.098004 28006 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:16:46.098022 28006 hybrid_clock.cc:648] HybridClock initialized: now 1786515406098022 us; error 0 us; skew 500 ppm
I20260812 06:16:46.103283 28006 webserver.cc:533] Webserver started at http://127.27.89.129:42597/ using document root <none> and password file <none>
I20260812 06:16:46.103552 28006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:46.103610 28006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:46.103737 28006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:46.104204 28006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/instance:
uuid: "d23f6efa2db6422dbae2fb3064d95bfe"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-h3ft"
I20260812 06:16:46.106040 28006 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:46.107250 28172 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:16:46.107534 28006 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:46.107621 28006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root
uuid: "d23f6efa2db6422dbae2fb3064d95bfe"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-h3ft"
I20260812 06:16:46.107734 28006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-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:16:46.113065 28006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:46.113586 28006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:46.114190 28006 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:46.115288 28006 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:46.115347 28006 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.115418 28006 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:46.115463 28006 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.122957 28006 rpc_server.cc:307] RPC server started. Bound to: 127.27.89.129:45599
I20260812 06:16:46.122983 28283 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.89.129:45599 every 8 connection(s)
I20260812 06:16:46.140686 28284 heartbeater.cc:344] Connected to a master server at 127.27.89.190:41377
I20260812 06:16:46.141098 28284 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:46.141688 28284 heartbeater.cc:507] Master 127.27.89.190:41377 requested a full tablet report, sending...
I20260812 06:16:46.144074 28060 ts_manager.cc:194] Registered new tserver with Master: d23f6efa2db6422dbae2fb3064d95bfe (127.27.89.129:45599)
I20260812 06:16:46.144393 28006 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020606788s
I20260812 06:16:46.146010 28060 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38644
I20260812 06:16:46.157492 28060 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38654:
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:16:46.177165 28223 tablet_service.cc:1511] Processing CreateTablet for tablet 351e1a254a264d72a557c3a746494810 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1fd3bbf548604fe0b754295027fae0e7]), partition=
I20260812 06:16:46.177721 28223 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 351e1a254a264d72a557c3a746494810. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:46.180624 28304 tablet_bootstrap.cc:492] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Bootstrap starting.
I20260812 06:16:46.181762 28304 tablet_bootstrap.cc:654] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.183122 28304 tablet_bootstrap.cc:492] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: No bootstrap required, opened a new log
I20260812 06:16:46.183250 28304 ts_tablet_manager.cc:1403] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:46.183805 28304 raft_consensus.cc:359] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d23f6efa2db6422dbae2fb3064d95bfe" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 45599 } }
I20260812 06:16:46.183946 28304 raft_consensus.cc:385] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.184036 28304 raft_consensus.cc:740] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d23f6efa2db6422dbae2fb3064d95bfe, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.184286 28304 consensus_queue.cc:260] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [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: "d23f6efa2db6422dbae2fb3064d95bfe" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 45599 } }
I20260812 06:16:46.184434 28304 raft_consensus.cc:399] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.184542 28304 raft_consensus.cc:493] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.184665 28304 raft_consensus.cc:3060] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.185523 28304 raft_consensus.cc:515] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d23f6efa2db6422dbae2fb3064d95bfe" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 45599 } }
I20260812 06:16:46.185690 28304 leader_election.cc:304] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [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: d23f6efa2db6422dbae2fb3064d95bfe; no voters: 
I20260812 06:16:46.185949 28304 leader_election.cc:290] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.186060 28306 raft_consensus.cc:2804] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.186261 28306 raft_consensus.cc:697] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 1 LEADER]: Becoming Leader. State: Replica: d23f6efa2db6422dbae2fb3064d95bfe, State: Running, Role: LEADER
I20260812 06:16:46.186419 28304 ts_tablet_manager.cc:1434] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:46.186496 28306 consensus_queue.cc:237] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [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: "d23f6efa2db6422dbae2fb3064d95bfe" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 45599 } }
I20260812 06:16:46.186789 28284 heartbeater.cc:499] Master 127.27.89.190:41377 was elected leader, sending a full tablet report...
I20260812 06:16:46.190100 28060 catalog_manager.cc:5719] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe reported cstate change: term changed from 0 to 1, leader changed from <none> to d23f6efa2db6422dbae2fb3064d95bfe (127.27.89.129). New cstate: current_term: 1 leader_uuid: "d23f6efa2db6422dbae2fb3064d95bfe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d23f6efa2db6422dbae2fb3064d95bfe" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 45599 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:46.318312 28006 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.118s	user 0.021s	sys 0.022s
I20260812 06:16:46.374323 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushMRSOp(351e1a254a264d72a557c3a746494810): perf score=6.156503
I20260812 06:16:46.582456 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushMRSOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.208s	user 0.136s	sys 0.016s Metrics: {"bytes_written":8205080,"cfile_init":1,"compiler_manager_pool.queue_time_us":3560,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1472,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42645,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":355,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"spinlock_wait_cycles":14592,"thread_start_us":146,"threads_started":1,"update_count":1000}
I20260812 06:16:46.583963 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:46.601661 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.602284 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810): 4103815 bytes on disk
I20260812 06:16:46.603053 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:16:46.603544 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:46.802802 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.199s	user 0.139s	sys 0.037s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446972,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2188,"lbm_read_time_us":11818,"lbm_reads_lt_1ms":364,"lbm_write_time_us":34640,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":937,"threads_started":5,"update_count":1500}
I20260812 06:16:46.803665 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=6.157687
I20260812 06:16:46.838546 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.035s	user 0.012s	sys 0.019s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11429,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:46.839550 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:46.958101 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.118s	user 0.069s	sys 0.049s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12344439,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":559,"lbm_read_time_us":10703,"lbm_reads_lt_1ms":267,"lbm_write_time_us":15471,"lbm_writes_lt_1ms":243,"mutex_wait_us":141,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":1000}
I20260812 06:16:46.959384 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=6.157687
I20260812 06:16:46.995340 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.036s	user 0.025s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14765,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:46.995986 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:47.103746 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.108s	user 0.076s	sys 0.024s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12344439,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":361,"lbm_read_time_us":6963,"lbm_reads_lt_1ms":263,"lbm_write_time_us":18477,"lbm_writes_lt_1ms":243,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":1000}
I20260812 06:16:47.104410 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=7.149875
I20260812 06:16:47.134850 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.030s	user 0.020s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":13360,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:47.135484 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:47.147879 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.148876 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:47.290355 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.141s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446961,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":9507,"lbm_reads_lt_1ms":372,"lbm_write_time_us":27089,"lbm_writes_lt_1ms":343,"mutex_wait_us":59,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.291111 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:47.333527 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.042s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18897,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.334162 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:47.448016 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.114s	user 0.095s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446852,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":192,"lbm_read_time_us":7204,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23083,"lbm_writes_lt_1ms":343,"mutex_wait_us":26,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":1500}
I20260812 06:16:47.448788 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:47.515332 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.066s	user 0.043s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19851,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.516119 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:47.535812 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.019s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.536681 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:47.710429 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.173s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":317,"lbm_read_time_us":12690,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28907,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.711190 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=7.149875
I20260812 06:16:47.755468 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.044s	user 0.021s	sys 0.022s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":17894,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":212,"reinsert_count":0,"update_count":1050}
I20260812 06:16:47.756347 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:47.786845 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.030s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6370,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.787667 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:47.800468 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.801014 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:47.969214 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.168s	user 0.131s	sys 0.035s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20549492,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":894,"lbm_read_time_us":12638,"lbm_reads_lt_1ms":473,"lbm_write_time_us":36869,"lbm_writes_lt_1ms":443,"mutex_wait_us":110,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:47.970232 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:48.030332 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.060s	user 0.031s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22565,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:48.030961 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:48.042634 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.043396 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:48.191373 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.148s	user 0.118s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":743,"lbm_read_time_us":10979,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29365,"lbm_writes_lt_1ms":443,"mutex_wait_us":379,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:16:48.192305 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:48.264441 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.072s	user 0.019s	sys 0.040s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22942,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:48.265255 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:48.278626 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.279296 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushMRSOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:48.314627 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushMRSOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1558,"drs_written":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2612,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:48.315809 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:48.492487 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.176s	user 0.121s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1610,"lbm_read_time_us":12108,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30564,"lbm_writes_lt_1ms":443,"mutex_wait_us":671,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24192,"update_count":2000}
I20260812 06:16:48.493484 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling LogGCOp(351e1a254a264d72a557c3a746494810): free 120965279 bytes of WAL
I20260812 06:16:48.494037 28180 log_reader.cc:385] T 351e1a254a264d72a557c3a746494810: removed 12 log segments from log reader
I20260812 06:16:48.494174 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000001 (ops 1-6)
I20260812 06:16:48.494302 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000002 (ops 7-10)
I20260812 06:16:48.494369 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000003 (ops 11-15)
I20260812 06:16:48.494446 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000004 (ops 16-20)
I20260812 06:16:48.494488 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000005 (ops 21-25)
I20260812 06:16:48.494524 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000006 (ops 26-30)
I20260812 06:16:48.494599 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000007 (ops 31-35)
I20260812 06:16:48.494642 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000008 (ops 36-40)
I20260812 06:16:48.494715 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000009 (ops 41-45)
I20260812 06:16:48.494756 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000010 (ops 46-50)
I20260812 06:16:48.494827 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000011 (ops 51-55)
I20260812 06:16:48.494868 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000012 (ops 56-60)
I20260812 06:16:48.533834 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: LogGCOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.040s	user 0.002s	sys 0.036s Metrics: {}
I20260812 06:16:48.534636 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=15.087375
I20260812 06:16:48.587350 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.052s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23087,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:48.587973 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810): 463 bytes on disk
I20260812 06:16:48.588465 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810) 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:16:48.588953 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:48.617640 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.028s	user 0.005s	sys 0.014s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.618266 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:48.629328 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4233,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.629868 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:48.854022 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.224s	user 0.155s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28754312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1112,"lbm_read_time_us":15836,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40473,"lbm_writes_lt_1ms":643,"mutex_wait_us":343,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3000}
I20260812 06:16:48.855340 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=11.118625
I20260812 06:16:48.899019 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.043s	user 0.007s	sys 0.033s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19662,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:48.900020 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:48.941895 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.041s	user 0.018s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6674,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.942708 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:48.963407 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.020s	user 0.020s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.964442 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:49.182510 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.218s	user 0.165s	sys 0.046s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651903,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":772,"lbm_read_time_us":14895,"lbm_reads_lt_1ms":573,"lbm_write_time_us":41929,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2500}
I20260812 06:16:49.183482 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=11.118625
I20260812 06:16:49.223824 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.040s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17555,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:49.224718 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:49.242067 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6064,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.242918 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:49.389266 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.146s	user 0.100s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549374,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":10487,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28727,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2000}
I20260812 06:16:49.390092 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:49.437104 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.047s	user 0.017s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21786,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.437983 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:49.458024 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.020s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.458613 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:49.606791 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.148s	user 0.124s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":11098,"lbm_reads_lt_1ms":464,"lbm_write_time_us":33591,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2000}
I20260812 06:16:49.607581 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:49.652406 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.042s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19692,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:49.653060 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:49.671756 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5307,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.672389 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:49.822631 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.150s	user 0.088s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549374,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":618,"lbm_read_time_us":9508,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30250,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:49.823459 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=14.095187
I20260812 06:16:49.886123 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.062s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23798,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.886729 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:49.899159 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.900599 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushMRSOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:49.931895 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushMRSOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.031s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1750,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1768,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:49.932875 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling LogGCOp(351e1a254a264d72a557c3a746494810): free 124257243 bytes of WAL
I20260812 06:16:49.933154 28180 log_reader.cc:385] T 351e1a254a264d72a557c3a746494810: removed 12 log segments from log reader
I20260812 06:16:49.933230 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000013 (ops 61-65)
I20260812 06:16:49.933295 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000014 (ops 66-70)
I20260812 06:16:49.933353 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000015 (ops 71-75)
I20260812 06:16:49.933398 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000016 (ops 76-80)
I20260812 06:16:49.933435 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000017 (ops 81-84)
I20260812 06:16:49.933483 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000018 (ops 85-89)
I20260812 06:16:49.933526 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000019 (ops 90-94)
I20260812 06:16:49.933565 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000020 (ops 95-99)
I20260812 06:16:49.933605 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000021 (ops 100-104)
I20260812 06:16:49.933645 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000022 (ops 105-109)
I20260812 06:16:49.933686 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000023 (ops 110-114)
I20260812 06:16:49.933735 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000024 (ops 115-119)
I20260812 06:16:49.964164 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: LogGCOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:49.964737 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:49.982900 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.018s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.983460 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810): 448 bytes on disk
I20260812 06:16:49.983909 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.984421 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:49.997105 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.997599 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:50.249540 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.252s	user 0.142s	sys 0.108s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32856855,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":650,"lbm_read_time_us":17426,"lbm_reads_lt_1ms":774,"lbm_write_time_us":50786,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":113,"threads_started":1,"update_count":3500}
I20260812 06:16:50.252214 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=15.087375
I20260812 06:16:50.311614 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.059s	user 0.047s	sys 0.011s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":27394,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:50.312216 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:50.328486 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.016s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.328969 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:50.339588 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.340095 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:50.546280 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.206s	user 0.170s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28754314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":201,"lbm_read_time_us":16113,"lbm_reads_lt_1ms":673,"lbm_write_time_us":44433,"lbm_writes_lt_1ms":643,"mutex_wait_us":66,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3000}
I20260812 06:16:50.547464 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=14.095187
I20260812 06:16:50.605430 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.058s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26442,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.606285 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:50.621773 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.622458 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:50.805501 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.183s	user 0.129s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":815,"lbm_read_time_us":13056,"lbm_reads_lt_1ms":564,"lbm_write_time_us":36948,"lbm_writes_lt_1ms":543,"mutex_wait_us":346,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:16:50.806308 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=11.118625
I20260812 06:16:50.858565 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.052s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":20944,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:50.859525 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:50.873863 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5381,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.874447 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:51.041576 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.167s	user 0.109s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549375,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":857,"lbm_read_time_us":11244,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27848,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.042303 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:51.085389 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.043s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20659,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:51.086197 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:51.209193 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.123s	user 0.086s	sys 0.035s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446851,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":657,"lbm_read_time_us":8362,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23445,"lbm_writes_lt_1ms":343,"mutex_wait_us":37,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":1500}
I20260812 06:16:51.209918 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:51.265903 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.056s	user 0.020s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23153,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:51.266635 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:51.279877 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.280877 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:51.437772 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.157s	user 0.084s	sys 0.072s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1146,"lbm_read_time_us":12309,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31361,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:16:51.438572 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=10.126437
I20260812 06:16:51.503373 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.065s	user 0.025s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:51.504199 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:51.523695 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.019s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.524672 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushMRSOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:51.561479 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushMRSOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.036s	user 0.023s	sys 0.007s Metrics: {"bytes_written":1152511,"cfile_init":1,"dirs.queue_time_us":133,"dirs.run_cpu_time_us":406,"dirs.run_wall_time_us":1918,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1936,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:51.562757 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:51.738324 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.175s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":11839,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29517,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:16:51.739449 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling LogGCOp(351e1a254a264d72a557c3a746494810): free 112239512 bytes of WAL
I20260812 06:16:51.739753 28180 log_reader.cc:385] T 351e1a254a264d72a557c3a746494810: removed 11 log segments from log reader
I20260812 06:16:51.739810 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000025 (ops 120-124)
I20260812 06:16:51.739866 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000026 (ops 125-129)
I20260812 06:16:51.739961 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000027 (ops 130-134)
I20260812 06:16:51.740015 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000028 (ops 135-139)
I20260812 06:16:51.740051 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000029 (ops 140-144)
I20260812 06:16:51.740113 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000030 (ops 145-148)
I20260812 06:16:51.740157 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000031 (ops 149-153)
I20260812 06:16:51.740227 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000032 (ops 154-158)
I20260812 06:16:51.740275 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000033 (ops 159-163)
I20260812 06:16:51.740310 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000034 (ops 164-168)
I20260812 06:16:51.740396 28180 log.cc:1079] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/351e1a254a264d72a557c3a746494810/wal-000000035 (ops 169-173)
I20260812 06:16:51.770241 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: LogGCOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:51.770984 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=14.095187
I20260812 06:16:51.824368 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.053s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24552,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.825129 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810): 447 bytes on disk
I20260812 06:16:51.825627 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: UndoDeltaBlockGCOp(351e1a254a264d72a557c3a746494810) 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:16:51.826310 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:51.844319 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.018s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.844980 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:52.027582 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.182s	user 0.135s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651796,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":12289,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34662,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:16:52.028355 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=11.118625
I20260812 06:16:52.075891 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.047s	user 0.033s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20677,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:52.076859 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:52.093423 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.016s	user 0.000s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5847,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:52.094267 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:52.261140 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.167s	user 0.132s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549373,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":528,"lbm_read_time_us":10605,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30958,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":90,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:16:52.261981 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=14.095187
I20260812 06:16:52.315888 28006 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.997s	user 2.084s	sys 0.148s
I20260812 06:16:52.320448 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.058s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23288,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.321069 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810): perf score=2.188937
I20260812 06:16:52.333511 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: FlushDeltaMemStoresOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":500}
I20260812 06:16:52.334313 28286 maintenance_manager.cc:419] P d23f6efa2db6422dbae2fb3064d95bfe: Scheduling MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810): perf score=1.000000
I20260812 06:16:52.371168 28006 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.004s	sys 0.000s
I20260812 06:16:52.371986 28006 tablet_server.cc:179] TabletServer@127.27.89.129:0 shutting down...
I20260812 06:16:52.466372 28180 maintenance_manager.cc:643] P d23f6efa2db6422dbae2fb3064d95bfe: MajorDeltaCompactionOp(351e1a254a264d72a557c3a746494810) complete. Timing: real 0.132s	user 0.088s	sys 0.044s Metrics: {"cfile_cache_hit":399,"cfile_cache_hit_bytes":16327745,"cfile_cache_miss":133,"cfile_cache_miss_bytes":8324048,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":853,"lbm_read_time_us":4463,"lbm_reads_lt_1ms":165,"lbm_write_time_us":32162,"lbm_writes_lt_1ms":543,"mutex_wait_us":98,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:16:52.467572 28006 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:52.468222 28006 tablet_replica.cc:333] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe: stopping tablet replica
I20260812 06:16:52.468565 28006 raft_consensus.cc:2243] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.468906 28006 raft_consensus.cc:2272] T 351e1a254a264d72a557c3a746494810 P d23f6efa2db6422dbae2fb3064d95bfe [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.489091 28006 tablet_server.cc:196] TabletServer@127.27.89.129:0 shutdown complete.
I20260812 06:16:52.514452 28006 master.cc:562] Master@127.27.89.190:41377 shutting down...
I20260812 06:16:52.519727 28006 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.519982 28006 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.520082 28006 tablet_replica.cc:333] T 00000000000000000000000000000000 P 97618ac8903a4d438e8145925a85782d: stopping tablet replica
I20260812 06:16:52.533594 28006 master.cc:584] Master@127.27.89.190:41377 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6704 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:52.653290 28006 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.89.190:39769
I20260812 06:16:52.653788 28006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:52.657555 28332 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:16:52.657555 28336 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:16:52.657711 28331 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:16:52.657776 28006 server_base.cc:1061] running on GCE node
I20260812 06:16:52.658157 28006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:52.658219 28006 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:16:52.658236 28006 hybrid_clock.cc:648] HybridClock initialized: now 1786515412658237 us; error 0 us; skew 500 ppm
I20260812 06:16:52.659338 28006 webserver.cc:533] Webserver started at http://127.27.89.190:37833/ using document root <none> and password file <none>
I20260812 06:16:52.659498 28006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:52.659547 28006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:52.659606 28006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:52.660010 28006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/master-0-root/instance:
uuid: "4aefe31837734c2ba831e1b0014a03a3"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-h3ft"
I20260812 06:16:52.661722 28006 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:52.662936 28350 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:16:52.663482 28006 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:52.663574 28006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/master-0-root
uuid: "4aefe31837734c2ba831e1b0014a03a3"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-h3ft"
I20260812 06:16:52.663692 28006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-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:16:52.670367 28006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:52.670907 28006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:52.675892 28006 rpc_server.cc:307] RPC server started. Bound to: 127.27.89.190:39769
I20260812 06:16:52.684543 28450 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.89.190:39769 every 8 connection(s)
I20260812 06:16:52.685201 28451 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:16:52.687578 28451 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3: Bootstrap starting.
I20260812 06:16:52.688545 28451 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:52.690126 28451 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3: No bootstrap required, opened a new log
I20260812 06:16:52.690665 28451 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4aefe31837734c2ba831e1b0014a03a3" member_type: VOTER }
I20260812 06:16:52.690802 28451 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:52.690850 28451 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4aefe31837734c2ba831e1b0014a03a3, State: Initialized, Role: FOLLOWER
I20260812 06:16:52.691118 28451 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [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: "4aefe31837734c2ba831e1b0014a03a3" member_type: VOTER }
I20260812 06:16:52.691238 28451 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:52.691287 28451 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:52.691349 28451 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:52.692255 28451 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4aefe31837734c2ba831e1b0014a03a3" member_type: VOTER }
I20260812 06:16:52.692433 28451 leader_election.cc:304] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [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: 4aefe31837734c2ba831e1b0014a03a3; no voters: 
I20260812 06:16:52.692716 28451 leader_election.cc:290] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:52.692986 28457 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:52.693387 28457 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 1 LEADER]: Becoming Leader. State: Replica: 4aefe31837734c2ba831e1b0014a03a3, State: Running, Role: LEADER
I20260812 06:16:52.693511 28451 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:52.693646 28457 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [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: "4aefe31837734c2ba831e1b0014a03a3" member_type: VOTER }
I20260812 06:16:52.694262 28460 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4aefe31837734c2ba831e1b0014a03a3. Latest consensus state: current_term: 1 leader_uuid: "4aefe31837734c2ba831e1b0014a03a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4aefe31837734c2ba831e1b0014a03a3" member_type: VOTER } }
I20260812 06:16:52.694376 28460 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:52.694521 28458 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4aefe31837734c2ba831e1b0014a03a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4aefe31837734c2ba831e1b0014a03a3" member_type: VOTER } }
I20260812 06:16:52.694602 28458 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:52.694800 28470 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:52.695972 28470 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:52.696231 28006 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:52.698325 28470 catalog_manager.cc:1383] Generated new cluster ID: dca99d2b97c546ac814eeb083c14eb0c
I20260812 06:16:52.698444 28470 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:52.721546 28470 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:52.722288 28470 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:52.729508 28470 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3: Generated new TSK 0
I20260812 06:16:52.729734 28470 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:52.761376 28006 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:52.764492 28487 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:16:52.764572 28491 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:16:52.764585 28486 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:16:52.764817 28006 server_base.cc:1061] running on GCE node
I20260812 06:16:52.765178 28006 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:52.765230 28006 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:16:52.765282 28006 hybrid_clock.cc:648] HybridClock initialized: now 1786515412765281 us; error 0 us; skew 500 ppm
I20260812 06:16:52.766373 28006 webserver.cc:533] Webserver started at http://127.27.89.129:33741/ using document root <none> and password file <none>
I20260812 06:16:52.766618 28006 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:52.766712 28006 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:52.766808 28006 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:52.767376 28006 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/instance:
uuid: "ce78870492e342a093e23049913467ef"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-h3ft"
I20260812 06:16:52.769191 28006 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:52.770467 28498 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:16:52.770876 28006 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:52.770989 28006 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root
uuid: "ce78870492e342a093e23049913467ef"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-h3ft"
I20260812 06:16:52.771140 28006 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-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:16:52.782017 28006 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:52.782467 28006 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:52.782828 28006 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:52.783442 28006 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:52.783514 28006 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:52.783568 28006 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:52.783632 28006 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:52.789235 28006 rpc_server.cc:307] RPC server started. Bound to: 127.27.89.129:43693
I20260812 06:16:52.789330 28615 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.89.129:43693 every 8 connection(s)
I20260812 06:16:52.799372 28618 heartbeater.cc:344] Connected to a master server at 127.27.89.190:39769
I20260812 06:16:52.799535 28618 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:52.799785 28618 heartbeater.cc:507] Master 127.27.89.190:39769 requested a full tablet report, sending...
I20260812 06:16:52.800778 28376 ts_manager.cc:194] Registered new tserver with Master: ce78870492e342a093e23049913467ef (127.27.89.129:43693)
I20260812 06:16:52.801136 28006 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011328552s
I20260812 06:16:52.801975 28376 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46624
I20260812 06:16:52.810663 28376 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46638:
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:16:52.822311 28548 tablet_service.cc:1511] Processing CreateTablet for tablet a372484a0c204cf68715100b4a680725 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1465dd6260bc4f8f9e96acd050392c07]), partition=
I20260812 06:16:52.822609 28548 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a372484a0c204cf68715100b4a680725. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:52.825592 28638 tablet_bootstrap.cc:492] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Bootstrap starting.
I20260812 06:16:52.826802 28638 tablet_bootstrap.cc:654] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:52.828478 28638 tablet_bootstrap.cc:492] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: No bootstrap required, opened a new log
I20260812 06:16:52.828569 28638 ts_tablet_manager.cc:1403] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:52.829140 28638 raft_consensus.cc:359] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce78870492e342a093e23049913467ef" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 43693 } }
I20260812 06:16:52.829267 28638 raft_consensus.cc:385] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:52.829293 28638 raft_consensus.cc:740] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ce78870492e342a093e23049913467ef, State: Initialized, Role: FOLLOWER
I20260812 06:16:52.829527 28638 consensus_queue.cc:260] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [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: "ce78870492e342a093e23049913467ef" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 43693 } }
I20260812 06:16:52.829609 28638 raft_consensus.cc:399] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:52.829635 28638 raft_consensus.cc:493] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:52.829725 28638 raft_consensus.cc:3060] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:52.830694 28638 raft_consensus.cc:515] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce78870492e342a093e23049913467ef" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 43693 } }
I20260812 06:16:52.830861 28638 leader_election.cc:304] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [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: ce78870492e342a093e23049913467ef; no voters: 
I20260812 06:16:52.831202 28638 leader_election.cc:290] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:52.831315 28640 raft_consensus.cc:2804] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:52.831580 28640 raft_consensus.cc:697] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 1 LEADER]: Becoming Leader. State: Replica: ce78870492e342a093e23049913467ef, State: Running, Role: LEADER
I20260812 06:16:52.831617 28638 ts_tablet_manager.cc:1434] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:52.831748 28640 consensus_queue.cc:237] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [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: "ce78870492e342a093e23049913467ef" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 43693 } }
I20260812 06:16:52.831869 28618 heartbeater.cc:499] Master 127.27.89.190:39769 was elected leader, sending a full tablet report...
I20260812 06:16:52.833635 28376 catalog_manager.cc:5719] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef reported cstate change: term changed from 0 to 1, leader changed from <none> to ce78870492e342a093e23049913467ef (127.27.89.129). New cstate: current_term: 1 leader_uuid: "ce78870492e342a093e23049913467ef" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce78870492e342a093e23049913467ef" member_type: VOTER last_known_addr { host: "127.27.89.129" port: 43693 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:52.909628 28006 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.070s	user 0.015s	sys 0.016s
I20260812 06:16:53.040383 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushMRSOp(a372484a0c204cf68715100b4a680725): perf score=15.086190
I20260812 06:16:53.186172 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushMRSOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.145s	user 0.101s	sys 0.036s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":121,"dirs.run_cpu_time_us":441,"dirs.run_wall_time_us":1181,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35569,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1000}
I20260812 06:16:53.187178 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling LogGCOp(a372484a0c204cf68715100b4a680725): free 8725963 bytes of WAL
I20260812 06:16:53.187438 28508 log_reader.cc:385] T a372484a0c204cf68715100b4a680725: removed 1 log segments from log reader
I20260812 06:16:53.187486 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000001 (ops 1-6)
I20260812 06:16:53.189666 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: LogGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:53.190140 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725): 12308955 bytes on disk
I20260812 06:16:53.190701 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:16:53.191239 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:53.212316 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6780,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.213120 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:53.365283 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.152s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":913,"lbm_read_time_us":11442,"lbm_reads_lt_1ms":360,"lbm_write_time_us":23188,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":542,"threads_started":5,"update_count":1500}
I20260812 06:16:53.366145 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:53.406311 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.040s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17859,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.407274 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:53.427687 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.428579 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:53.595911 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.167s	user 0.125s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1960,"lbm_read_time_us":12419,"lbm_reads_lt_1ms":472,"lbm_write_time_us":33166,"lbm_writes_lt_1ms":443,"mutex_wait_us":1419,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29696,"update_count":2000}
I20260812 06:16:53.596917 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:53.647944 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.051s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17321,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.648666 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:53.663286 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.664023 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:53.817754 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.153s	user 0.110s	sys 0.043s 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":1185,"lbm_read_time_us":10849,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29962,"lbm_writes_lt_1ms":443,"mutex_wait_us":407,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:16:53.818463 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:53.883143 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.064s	user 0.037s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22966,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.883841 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:53.895962 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.896533 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:54.086083 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.189s	user 0.124s	sys 0.064s 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":1438,"lbm_read_time_us":14733,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31901,"lbm_writes_lt_1ms":443,"mutex_wait_us":389,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.086848 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:54.131896 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.045s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19695,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.132529 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:54.264232 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.131s	user 0.091s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1067,"lbm_read_time_us":8731,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24368,"lbm_writes_lt_1ms":343,"mutex_wait_us":333,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:16:54.265077 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:54.307756 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.042s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18377,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.308427 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:54.442394 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.134s	user 0.110s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":237,"lbm_read_time_us":9320,"lbm_reads_lt_1ms":363,"lbm_write_time_us":25924,"lbm_writes_lt_1ms":343,"mutex_wait_us":92,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.443444 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:54.498816 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.055s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18787,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.499943 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:54.514276 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.514853 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:54.657713 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.143s	user 0.105s	sys 0.035s 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":788,"lbm_read_time_us":10696,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27793,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:16:54.658723 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:54.715526 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.057s	user 0.035s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20991,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.716275 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:54.730134 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.014s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.730764 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushMRSOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:54.767911 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushMRSOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.037s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":110,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1625,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2670,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:54.768837 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling LogGCOp(a372484a0c204cf68715100b4a680725): free 127961101 bytes of WAL
I20260812 06:16:54.769135 28508 log_reader.cc:385] T a372484a0c204cf68715100b4a680725: removed 12 log segments from log reader
I20260812 06:16:54.769186 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000002 (ops 7-11)
I20260812 06:16:54.769222 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000003 (ops 12-16)
I20260812 06:16:54.769304 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000004 (ops 17-21)
I20260812 06:16:54.769342 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000005 (ops 22-26)
I20260812 06:16:54.769402 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000006 (ops 27-31)
I20260812 06:16:54.769480 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000007 (ops 32-36)
I20260812 06:16:54.769526 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000008 (ops 37-41)
I20260812 06:16:54.769600 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000009 (ops 42-46)
I20260812 06:16:54.769645 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000010 (ops 47-51)
I20260812 06:16:54.769675 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000011 (ops 52-56)
I20260812 06:16:54.769744 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000012 (ops 57-61)
I20260812 06:16:54.769793 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000013 (ops 62-66)
I20260812 06:16:54.807895 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: LogGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.039s	user 0.000s	sys 0.038s Metrics: {}
I20260812 06:16:54.808543 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725): 462 bytes on disk
I20260812 06:16:54.809345 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:16:54.809965 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=5.165500
I20260812 06:16:54.837379 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.027s	user 0.017s	sys 0.007s Metrics: {"bytes_written":6605134,"delete_count":0,"lbm_write_time_us":11269,"lbm_writes_lt_1ms":164,"reinsert_count":0,"update_count":805}
I20260812 06:16:54.838291 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:54.851198 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":1600127,"delete_count":0,"lbm_write_time_us":3523,"lbm_writes_lt_1ms":42,"reinsert_count":0,"update_count":195}
I20260812 06:16:54.851953 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:55.054725 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.203s	user 0.157s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":957,"lbm_read_time_us":15391,"lbm_reads_lt_1ms":666,"lbm_write_time_us":38939,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20480,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:16:55.056231 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:55.125145 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.069s	user 0.034s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":33697,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:16:55.126005 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:55.142030 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.142764 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:55.327818 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.185s	user 0.156s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":12711,"lbm_reads_lt_1ms":564,"lbm_write_time_us":38496,"lbm_writes_lt_1ms":543,"mutex_wait_us":98,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:55.328641 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:55.399889 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.071s	user 0.025s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28691,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.400697 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:55.414506 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.415630 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:55.611227 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.195s	user 0.148s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":551,"lbm_read_time_us":14680,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39228,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2500}
I20260812 06:16:55.612087 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:55.676898 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.065s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24141,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.677626 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:55.691434 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.693197 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:55.904181 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.211s	user 0.146s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1940,"lbm_read_time_us":13549,"lbm_reads_lt_1ms":572,"lbm_write_time_us":40250,"lbm_writes_lt_1ms":543,"mutex_wait_us":607,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":52224,"update_count":2500}
I20260812 06:16:55.905090 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:55.993520 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.088s	user 0.026s	sys 0.044s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":33229,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.994274 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:56.008900 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.009559 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:56.219573 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.210s	user 0.133s	sys 0.075s 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":1167,"lbm_read_time_us":13634,"lbm_reads_lt_1ms":572,"lbm_write_time_us":40606,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:16:56.220346 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:56.293433 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.073s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24825,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.294205 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:56.308995 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.309593 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:56.523281 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.213s	user 0.139s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":440,"lbm_read_time_us":14142,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37207,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:16:56.524173 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:56.609910 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.085s	user 0.028s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24131,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.611071 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:56.633947 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.023s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.634940 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushMRSOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:56.685699 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushMRSOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.050s	user 0.041s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1655,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2158,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:56.686506 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling LogGCOp(a372484a0c204cf68715100b4a680725): free 129320510 bytes of WAL
I20260812 06:16:56.686796 28508 log_reader.cc:385] T a372484a0c204cf68715100b4a680725: removed 13 log segments from log reader
I20260812 06:16:56.686848 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000014 (ops 67-71)
I20260812 06:16:56.686882 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000015 (ops 72-76)
I20260812 06:16:56.686901 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000016 (ops 77-81)
I20260812 06:16:56.686986 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000017 (ops 82-86)
I20260812 06:16:56.687175 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000018 (ops 87-91)
I20260812 06:16:56.687225 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000019 (ops 92-96)
I20260812 06:16:56.687244 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000020 (ops 97-100)
I20260812 06:16:56.687263 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000021 (ops 101-105)
I20260812 06:16:56.687306 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000022 (ops 106-110)
I20260812 06:16:56.687356 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000023 (ops 111-115)
I20260812 06:16:56.687400 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000024 (ops 116-120)
I20260812 06:16:56.687444 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000025 (ops 121-124)
I20260812 06:16:56.687485 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000026 (ops 125-129)
I20260812 06:16:56.721170 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: LogGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.034s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:16:56.721916 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=3.181125
I20260812 06:16:56.748935 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.027s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5582,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:56.749675 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:56.764425 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5564,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:56.765202 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725): 493 bytes on disk
I20260812 06:16:56.766052 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":131,"lbm_reads_lt_1ms":4}
I20260812 06:16:56.766827 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:57.053018 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.286s	user 0.195s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938775,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":755,"lbm_read_time_us":20565,"lbm_reads_lt_1ms":774,"lbm_write_time_us":47951,"lbm_writes_lt_1ms":743,"mutex_wait_us":65,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":410,"threads_started":5,"update_count":3500}
I20260812 06:16:57.054124 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=15.087375
I20260812 06:16:57.118417 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.064s	user 0.045s	sys 0.015s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":26194,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:57.119150 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:57.142382 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.023s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.143220 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:57.160261 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6218,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:57.161305 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:57.387362 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.226s	user 0.137s	sys 0.088s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836244,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":926,"lbm_read_time_us":17292,"lbm_reads_lt_1ms":673,"lbm_write_time_us":41080,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:16:57.388238 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:57.451398 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.063s	user 0.030s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22940,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.452133 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:57.469357 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.470140 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:57.679287 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.209s	user 0.159s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1235,"lbm_read_time_us":15072,"lbm_reads_lt_1ms":564,"lbm_write_time_us":39993,"lbm_writes_lt_1ms":543,"mutex_wait_us":199,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:16:57.680133 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=14.095187
I20260812 06:16:57.734653 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.054s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25364,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.735591 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:57.927692 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.192s	user 0.126s	sys 0.061s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":306,"lbm_read_time_us":13265,"lbm_reads_lt_1ms":467,"lbm_write_time_us":31524,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:16:57.928740 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=11.118625
I20260812 06:16:57.980026 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.051s	user 0.030s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20600,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:57.980919 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:58.000514 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:16:58.001163 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:58.013263 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.012s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4570,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.014250 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:58.223852 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.209s	user 0.107s	sys 0.099s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":321,"lbm_read_time_us":14197,"lbm_reads_lt_1ms":573,"lbm_write_time_us":40180,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:16:58.224645 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=11.118625
I20260812 06:16:58.263792 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.039s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17910,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:58.264601 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:58.287459 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.023s	user 0.014s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7225,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.288295 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:58.437528 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.149s	user 0.132s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":477,"lbm_read_time_us":12054,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29157,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:16:58.438531 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=10.126437
I20260812 06:16:58.488552 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.050s	user 0.027s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22936,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:58.489591 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushMRSOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:58.534672 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushMRSOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.045s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":121,"dirs.run_cpu_time_us":399,"dirs.run_wall_time_us":1743,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1775,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:58.535660 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725): 473 bytes on disk
I20260812 06:16:58.536108 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: UndoDeltaBlockGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.536810 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=3.181125
I20260812 06:16:58.550469 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5266,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:58.551292 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling LogGCOp(a372484a0c204cf68715100b4a680725): free 124257506 bytes of WAL
I20260812 06:16:58.551672 28508 log_reader.cc:385] T a372484a0c204cf68715100b4a680725: removed 12 log segments from log reader
I20260812 06:16:58.551759 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000027 (ops 130-134)
I20260812 06:16:58.551805 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000028 (ops 135-139)
I20260812 06:16:58.551854 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000029 (ops 140-144)
I20260812 06:16:58.551882 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000030 (ops 145-149)
I20260812 06:16:58.551916 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000031 (ops 150-154)
I20260812 06:16:58.551942 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000032 (ops 155-159)
I20260812 06:16:58.551968 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000033 (ops 160-164)
I20260812 06:16:58.551995 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000034 (ops 165-169)
I20260812 06:16:58.552022 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000035 (ops 170-174)
I20260812 06:16:58.552052 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000036 (ops 175-178)
I20260812 06:16:58.552098 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000037 (ops 179-183)
I20260812 06:16:58.552126 28508 log.cc:1079] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: Deleting log segment in path: /tmp/dist-test-taskmW81x7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515405923687-28006-0/minicluster-data/ts-0-root/wals/a372484a0c204cf68715100b4a680725/wal-000000038 (ops 184-188)
I20260812 06:16:58.589910 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: LogGCOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.038s	user 0.004s	sys 0.032s Metrics: {}
I20260812 06:16:58.590540 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:58.617754 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.027s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5865,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.618958 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:58.632076 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.632683 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:58.825433 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.193s	user 0.143s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":762,"lbm_read_time_us":14557,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39185,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:16:58.826318 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=11.118625
I20260812 06:16:58.849682 28006 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.940s	user 2.195s	sys 0.171s
I20260812 06:16:58.867686 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.041s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18839,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1550}
I20260812 06:16:58.868600 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725): perf score=2.188937
I20260812 06:16:58.889554 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: FlushDeltaMemStoresOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.021s	user 0.014s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7441,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.890357 28619 maintenance_manager.cc:419] P ce78870492e342a093e23049913467ef: Scheduling MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725): perf score=1.000000
I20260812 06:16:58.897119 28006 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.047s	user 0.002s	sys 0.000s
I20260812 06:16:58.897778 28006 tablet_server.cc:179] TabletServer@127.27.89.129:0 shutting down...
I20260812 06:16:59.021389 28508 maintenance_manager.cc:643] P ce78870492e342a093e23049913467ef: MajorDeltaCompactionOp(a372484a0c204cf68715100b4a680725) complete. Timing: real 0.131s	user 0.114s	sys 0.016s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":402,"cfile_cache_miss_bytes":16409878,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1166,"lbm_read_time_us":9273,"lbm_reads_lt_1ms":418,"lbm_write_time_us":25651,"lbm_writes_lt_1ms":443,"mutex_wait_us":298,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:16:59.022516 28006 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:59.022789 28006 tablet_replica.cc:333] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef: stopping tablet replica
I20260812 06:16:59.022972 28006 raft_consensus.cc:2243] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:59.023247 28006 raft_consensus.cc:2272] T a372484a0c204cf68715100b4a680725 P ce78870492e342a093e23049913467ef [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:59.028316 28006 tablet_server.cc:196] TabletServer@127.27.89.129:0 shutdown complete.
I20260812 06:16:59.061615 28006 master.cc:562] Master@127.27.89.190:39769 shutting down...
I20260812 06:16:59.066017 28006 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:59.066265 28006 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:59.066324 28006 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4aefe31837734c2ba831e1b0014a03a3: stopping tablet replica
I20260812 06:16:59.079850 28006 master.cc:584] Master@127.27.89.190:39769 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6545 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13251 ms total)

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