[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:37.472011 20227 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.192.254:42205
I20260812 06:19:37.473155 20227 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:37.473842 20227 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:37.480580 20237 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:37.480741 20227 server_base.cc:1061] running on GCE node
W20260812 06:19:37.480639 20236 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:37.480944 20240 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:37.481531 20227 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:37.481647 20227 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:37.481702 20227 hybrid_clock.cc:648] HybridClock initialized: now 1786515577481696 us; error 0 us; skew 500 ppm
I20260812 06:19:37.483659 20227 webserver.cc:533] Webserver started at http://127.19.192.254:46267/ using document root <none> and password file <none>
I20260812 06:19:37.484295 20227 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:37.484359 20227 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:37.484647 20227 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:37.486459 20227 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/master-0-root/instance:
uuid: "67247dc4c6534d628a41a7fe9406b648"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-twwt"
I20260812 06:19:37.490373 20227 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:37.492736 20249 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.493825 20227 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:37.494060 20227 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/master-0-root
uuid: "67247dc4c6534d628a41a7fe9406b648"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-twwt"
I20260812 06:19:37.494172 20227 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:37.504115 20227 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:37.504719 20227 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:37.504899 20227 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:37.512540 20227 rpc_server.cc:307] RPC server started. Bound to: 127.19.192.254:42205
I20260812 06:19:37.512585 20332 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.192.254:42205 every 8 connection(s)
I20260812 06:19:37.515084 20333 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:37.520746 20333 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648: Bootstrap starting.
I20260812 06:19:37.523347 20333 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:37.524308 20333 log.cc:826] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:37.526136 20333 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648: No bootstrap required, opened a new log
I20260812 06:19:37.529121 20333 raft_consensus.cc:359] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67247dc4c6534d628a41a7fe9406b648" member_type: VOTER }
I20260812 06:19:37.529295 20333 raft_consensus.cc:385] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:37.529384 20333 raft_consensus.cc:740] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 67247dc4c6534d628a41a7fe9406b648, State: Initialized, Role: FOLLOWER
I20260812 06:19:37.530097 20333 consensus_queue.cc:260] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [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: "67247dc4c6534d628a41a7fe9406b648" member_type: VOTER }
I20260812 06:19:37.530296 20333 raft_consensus.cc:399] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:37.530366 20333 raft_consensus.cc:493] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:37.530514 20333 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:37.531376 20333 raft_consensus.cc:515] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67247dc4c6534d628a41a7fe9406b648" member_type: VOTER }
I20260812 06:19:37.531862 20333 leader_election.cc:304] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [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: 67247dc4c6534d628a41a7fe9406b648; no voters: 
I20260812 06:19:37.532230 20333 leader_election.cc:290] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:37.532439 20339 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:37.532719 20339 raft_consensus.cc:697] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 1 LEADER]: Becoming Leader. State: Replica: 67247dc4c6534d628a41a7fe9406b648, State: Running, Role: LEADER
I20260812 06:19:37.533160 20339 consensus_queue.cc:237] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [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: "67247dc4c6534d628a41a7fe9406b648" member_type: VOTER }
I20260812 06:19:37.533371 20333 sys_catalog.cc:565] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:37.535140 20343 sys_catalog.cc:455] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 67247dc4c6534d628a41a7fe9406b648. Latest consensus state: current_term: 1 leader_uuid: "67247dc4c6534d628a41a7fe9406b648" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67247dc4c6534d628a41a7fe9406b648" member_type: VOTER } }
I20260812 06:19:37.535184 20340 sys_catalog.cc:455] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "67247dc4c6534d628a41a7fe9406b648" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67247dc4c6534d628a41a7fe9406b648" member_type: VOTER } }
I20260812 06:19:37.535266 20343 sys_catalog.cc:458] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:37.535303 20340 sys_catalog.cc:458] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:37.535660 20354 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:37.535969 20227 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:37.538666 20354 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:37.544445 20354 catalog_manager.cc:1383] Generated new cluster ID: b05a6a7e05c8487db8e2946fbcff0617
I20260812 06:19:37.544586 20354 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:37.570330 20354 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:37.571372 20354 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:37.579347 20354 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648: Generated new TSK 0
I20260812 06:19:37.580142 20354 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:37.601109 20227 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:37.604425 20368 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:37.604446 20367 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:37.604521 20372 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:37.604733 20227 server_base.cc:1061] running on GCE node
I20260812 06:19:37.605050 20227 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:37.605100 20227 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:37.605116 20227 hybrid_clock.cc:648] HybridClock initialized: now 1786515577605116 us; error 0 us; skew 500 ppm
I20260812 06:19:37.606197 20227 webserver.cc:533] Webserver started at http://127.19.192.193:32959/ using document root <none> and password file <none>
I20260812 06:19:37.606406 20227 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:37.606489 20227 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:37.606583 20227 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:37.607064 20227 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/instance:
uuid: "2ced33255b5849b7a9f9c7f6dd9965d9"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-twwt"
I20260812 06:19:37.608747 20227 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:37.609951 20380 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.610234 20227 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:37.610303 20227 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root
uuid: "2ced33255b5849b7a9f9c7f6dd9965d9"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-twwt"
I20260812 06:19:37.610400 20227 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:37.635042 20227 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:37.635679 20227 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:37.636341 20227 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:37.637333 20227 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:37.637389 20227 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.637434 20227 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:37.637493 20227 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.644474 20227 rpc_server.cc:307] RPC server started. Bound to: 127.19.192.193:36001
I20260812 06:19:37.644502 20470 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.192.193:36001 every 8 connection(s)
I20260812 06:19:37.659783 20471 heartbeater.cc:344] Connected to a master server at 127.19.192.254:42205
I20260812 06:19:37.660130 20471 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:37.660643 20471 heartbeater.cc:507] Master 127.19.192.254:42205 requested a full tablet report, sending...
I20260812 06:19:37.662340 20270 ts_manager.cc:194] Registered new tserver with Master: 2ced33255b5849b7a9f9c7f6dd9965d9 (127.19.192.193:36001)
I20260812 06:19:37.662557 20227 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017408187s
I20260812 06:19:37.663820 20270 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57230
I20260812 06:19:37.673982 20270 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57240:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:37.690112 20416 tablet_service.cc:1511] Processing CreateTablet for tablet 00c76ba3837644b4846ce3716c7629b6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0dc09ee5374741729a02af0524c4f7ae]), partition=
I20260812 06:19:37.690755 20416 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00c76ba3837644b4846ce3716c7629b6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:37.693552 20495 tablet_bootstrap.cc:492] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Bootstrap starting.
I20260812 06:19:37.695036 20495 tablet_bootstrap.cc:654] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:37.696410 20495 tablet_bootstrap.cc:492] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: No bootstrap required, opened a new log
I20260812 06:19:37.696507 20495 ts_tablet_manager.cc:1403] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:37.697275 20495 raft_consensus.cc:359] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ced33255b5849b7a9f9c7f6dd9965d9" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 36001 } }
I20260812 06:19:37.697429 20495 raft_consensus.cc:385] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:37.697489 20495 raft_consensus.cc:740] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2ced33255b5849b7a9f9c7f6dd9965d9, State: Initialized, Role: FOLLOWER
I20260812 06:19:37.697669 20495 consensus_queue.cc:260] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [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: "2ced33255b5849b7a9f9c7f6dd9965d9" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 36001 } }
I20260812 06:19:37.697793 20495 raft_consensus.cc:399] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:37.697854 20495 raft_consensus.cc:493] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:37.697921 20495 raft_consensus.cc:3060] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:37.698796 20495 raft_consensus.cc:515] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ced33255b5849b7a9f9c7f6dd9965d9" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 36001 } }
I20260812 06:19:37.698956 20495 leader_election.cc:304] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [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: 2ced33255b5849b7a9f9c7f6dd9965d9; no voters: 
I20260812 06:19:37.699241 20495 leader_election.cc:290] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:37.699345 20498 raft_consensus.cc:2804] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:37.699565 20498 raft_consensus.cc:697] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 1 LEADER]: Becoming Leader. State: Replica: 2ced33255b5849b7a9f9c7f6dd9965d9, State: Running, Role: LEADER
I20260812 06:19:37.699666 20495 ts_tablet_manager.cc:1434] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:37.699728 20498 consensus_queue.cc:237] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [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: "2ced33255b5849b7a9f9c7f6dd9965d9" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 36001 } }
I20260812 06:19:37.700132 20471 heartbeater.cc:499] Master 127.19.192.254:42205 was elected leader, sending a full tablet report...
I20260812 06:19:37.703171 20270 catalog_manager.cc:5719] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2ced33255b5849b7a9f9c7f6dd9965d9 (127.19.192.193). New cstate: current_term: 1 leader_uuid: "2ced33255b5849b7a9f9c7f6dd9965d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ced33255b5849b7a9f9c7f6dd9965d9" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 36001 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:37.773008 20227 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.028s	sys 0.000s
I20260812 06:19:37.895830 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushMRSOp(00c76ba3837644b4846ce3716c7629b6): perf score=15.086190
I20260812 06:19:38.053777 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushMRSOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.157s	user 0.115s	sys 0.040s Metrics: {"bytes_written":9805020,"cfile_init":1,"compiler_manager_pool.queue_time_us":323,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":950,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36924,"lbm_writes_lt_1ms":596,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":79616,"thread_start_us":188,"threads_started":1,"update_count":1195}
I20260812 06:19:38.055444 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling LogGCOp(00c76ba3837644b4846ce3716c7629b6): free 8725963 bytes of WAL
I20260812 06:19:38.055887 20386 log_reader.cc:385] T 00c76ba3837644b4846ce3716c7629b6: removed 1 log segments from log reader
I20260812 06:19:38.056025 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000001 (ops 1-6)
I20260812 06:19:38.058816 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: LogGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:38.059253 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.196750
I20260812 06:19:38.069553 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2748834,"delete_count":0,"lbm_write_time_us":3592,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:38.070003 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6): 12308956 bytes on disk
I20260812 06:19:38.070569 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.071045 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:38.200544 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.129s	user 0.101s	sys 0.019s Metrics: {"cfile_cache_miss":338,"cfile_cache_miss_bytes":16775017,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":392,"lbm_read_time_us":6687,"lbm_reads_lt_1ms":366,"lbm_write_time_us":22175,"lbm_writes_lt_1ms":349,"mutex_wait_us":46,"peak_mem_usage":38508966,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":266,"threads_started":5,"update_count":1530}
I20260812 06:19:38.201059 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:38.250941 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.050s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12061349,"delete_count":0,"lbm_write_time_us":17841,"lbm_writes_lt_1ms":297,"reinsert_count":0,"update_count":1470}
I20260812 06:19:38.251401 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:38.262308 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.263027 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:38.384440 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.121s	user 0.087s	sys 0.034s Metrics: {"cfile_cache_miss":426,"cfile_cache_miss_bytes":20385171,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":9636,"lbm_reads_lt_1ms":466,"lbm_write_time_us":22989,"lbm_writes_lt_1ms":437,"mutex_wait_us":64,"peak_mem_usage":49402734,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":1970}
I20260812 06:19:38.385056 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:38.437505 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.052s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16666,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.438105 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:38.454962 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.017s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6432,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.455492 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:38.618201 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.163s	user 0.124s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":11470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25181,"lbm_writes_lt_1ms":443,"mutex_wait_us":92,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.618971 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:38.668784 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.050s	user 0.025s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16046,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.669404 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:38.682596 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.683115 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:38.817715 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.134s	user 0.110s	sys 0.024s 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":207,"lbm_read_time_us":9081,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27166,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:19:38.818538 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:38.863677 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.045s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16959,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.864234 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:38.876937 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.877563 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:39.020882 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.143s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":756,"lbm_read_time_us":10274,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28685,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:19:39.021522 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:39.075598 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.054s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18132,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.077049 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:39.087128 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.010s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1353980,"delete_count":0,"lbm_write_time_us":1557,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:19:39.087622 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.196750
I20260812 06:19:39.095754 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":2795,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:39.096222 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:39.250758 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.154s	user 0.106s	sys 0.048s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1040,"lbm_read_time_us":11999,"lbm_reads_lt_1ms":473,"lbm_write_time_us":25717,"lbm_writes_lt_1ms":443,"mutex_wait_us":378,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":77440,"update_count":2000}
I20260812 06:19:39.251477 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:39.296495 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.045s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19153,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.297034 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:39.313344 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.314015 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:39.448493 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.134s	user 0.109s	sys 0.023s 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":862,"lbm_read_time_us":10977,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26352,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:19:39.449115 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:39.492563 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.043s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14662,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.493209 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:39.504515 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.505218 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushMRSOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:39.536872 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushMRSOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":137,"dirs.run_cpu_time_us":423,"dirs.run_wall_time_us":1641,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1676,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:39.537834 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling LogGCOp(00c76ba3837644b4846ce3716c7629b6): free 132118262 bytes of WAL
I20260812 06:19:39.538156 20386 log_reader.cc:385] T 00c76ba3837644b4846ce3716c7629b6: removed 13 log segments from log reader
I20260812 06:19:39.538225 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000002 (ops 7-11)
I20260812 06:19:39.538276 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000003 (ops 12-16)
I20260812 06:19:39.538316 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000004 (ops 17-21)
I20260812 06:19:39.538349 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000005 (ops 22-26)
I20260812 06:19:39.538381 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000006 (ops 27-30)
I20260812 06:19:39.538417 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000007 (ops 31-35)
I20260812 06:19:39.538456 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000008 (ops 36-40)
I20260812 06:19:39.538491 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000009 (ops 41-44)
I20260812 06:19:39.538524 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000010 (ops 45-49)
I20260812 06:19:39.538558 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000011 (ops 50-54)
I20260812 06:19:39.538590 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000012 (ops 55-59)
I20260812 06:19:39.538661 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000013 (ops 60-64)
I20260812 06:19:39.538698 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000014 (ops 65-68)
I20260812 06:19:39.576287 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: LogGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.038s	user 0.000s	sys 0.037s Metrics: {}
I20260812 06:19:39.576951 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:39.591621 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4225731,"delete_count":0,"lbm_write_time_us":4844,"lbm_writes_lt_1ms":106,"mutex_wait_us":94,"reinsert_count":0,"update_count":515}
I20260812 06:19:39.592103 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:39.603785 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3979583,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:39.604303 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6): 482 bytes on disk
I20260812 06:19:39.604992 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4}
I20260812 06:19:39.605834 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:39.796651 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.191s	user 0.139s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836372,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":809,"lbm_read_time_us":14590,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36568,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:39.797422 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:39.847512 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.050s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":21839,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.848013 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:39.861531 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.862057 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:40.024904 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.163s	user 0.124s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733719,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":10929,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31492,"lbm_writes_lt_1ms":543,"mutex_wait_us":80,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:40.027037 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:40.092497 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.065s	user 0.032s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24737,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:40.093109 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:40.104274 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.104933 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:40.292739 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.188s	user 0.106s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":786,"lbm_read_time_us":13876,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32866,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2500}
I20260812 06:19:40.293486 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:40.348248 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.055s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23570,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.348747 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:40.497939 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.149s	user 0.085s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631189,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":146,"lbm_read_time_us":10029,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25021,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:19:40.498720 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:40.548337 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.049s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21474,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.549130 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:40.561363 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.562099 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:40.747668 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.185s	user 0.126s	sys 0.059s 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":267,"lbm_read_time_us":12418,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31307,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:40.748242 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:40.799382 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22813,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.799923 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:40.816422 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.817655 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:40.994858 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.177s	user 0.145s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":873,"lbm_read_time_us":12563,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36082,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:40.995544 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:41.037303 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.042s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16464,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.037978 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:41.049330 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.049871 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushMRSOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:41.082026 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushMRSOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.032s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":1235,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1582,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:41.083007 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling LogGCOp(00c76ba3837644b4846ce3716c7629b6): free 129320466 bytes of WAL
I20260812 06:19:41.083312 20386 log_reader.cc:385] T 00c76ba3837644b4846ce3716c7629b6: removed 13 log segments from log reader
I20260812 06:19:41.083388 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000015 (ops 69-73)
I20260812 06:19:41.083446 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000016 (ops 74-78)
I20260812 06:19:41.083500 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000017 (ops 79-83)
I20260812 06:19:41.083534 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000018 (ops 84-88)
I20260812 06:19:41.083580 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000019 (ops 89-92)
I20260812 06:19:41.083606 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000020 (ops 93-97)
I20260812 06:19:41.083636 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000021 (ops 98-102)
I20260812 06:19:41.083685 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000022 (ops 103-106)
I20260812 06:19:41.083734 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000023 (ops 107-111)
I20260812 06:19:41.083781 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000024 (ops 112-116)
I20260812 06:19:41.083815 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000025 (ops 117-121)
I20260812 06:19:41.083858 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000026 (ops 122-126)
I20260812 06:19:41.083889 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000027 (ops 127-131)
I20260812 06:19:41.116237 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: LogGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:41.116783 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6): 472 bytes on disk
I20260812 06:19:41.117326 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.117894 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=3.181125
I20260812 06:19:41.133373 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":5005190,"delete_count":0,"lbm_write_time_us":6162,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:19:41.133889 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:41.147785 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":4857,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:19:41.148403 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:41.352057 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.203s	user 0.147s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836351,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":213,"lbm_read_time_us":13274,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39034,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:41.352805 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:41.402838 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.050s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.403414 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:41.419060 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.015s	user 0.011s	sys 0.004s 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:19:41.419612 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:41.621497 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.202s	user 0.134s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":14343,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31331,"lbm_writes_lt_1ms":543,"mutex_wait_us":103,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2500}
I20260812 06:19:41.622192 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:41.673797 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.051s	user 0.039s	sys 0.007s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22011,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.674304 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:41.688027 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.014s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4904,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.688680 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:41.870398 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.181s	user 0.139s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733727,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":745,"lbm_read_time_us":13575,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35518,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:19:41.871040 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:41.924259 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.053s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21067,"lbm_writes_lt_1ms":403,"mutex_wait_us":18,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.924786 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:41.941062 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.941895 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:42.098191 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.156s	user 0.132s	sys 0.024s 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":397,"lbm_read_time_us":12409,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31716,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:42.099050 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=11.118625
I20260812 06:19:42.143642 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.044s	user 0.035s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19259,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:42.144487 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:42.174341 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.029s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5626,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.174944 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:42.186836 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.187695 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:42.355746 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.168s	user 0.136s	sys 0.031s 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":1101,"lbm_read_time_us":12877,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33807,"lbm_writes_lt_1ms":543,"mutex_wait_us":318,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:19:42.356719 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=12.110812
I20260812 06:19:42.402048 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.045s	user 0.028s	sys 0.014s Metrics: {"bytes_written":13948452,"delete_count":0,"lbm_write_time_us":19176,"lbm_writes_lt_1ms":343,"reinsert_count":0,"update_count":1700}
I20260812 06:19:42.402878 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.196750
I20260812 06:19:42.412359 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":2944,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:19:42.413028 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:42.570770 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.158s	user 0.111s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631269,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":9650,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26244,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:42.571540 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=14.095187
I20260812 06:19:42.622694 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.051s	user 0.045s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21491,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.623401 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:42.650009 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.026s	user 0.006s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.650734 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushMRSOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:42.688763 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushMRSOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.038s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1517,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1806,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:42.689553 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling LogGCOp(00c76ba3837644b4846ce3716c7629b6): free 120553703 bytes of WAL
I20260812 06:19:42.689817 20386 log_reader.cc:385] T 00c76ba3837644b4846ce3716c7629b6: removed 12 log segments from log reader
I20260812 06:19:42.689874 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000028 (ops 132-136)
I20260812 06:19:42.689905 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000029 (ops 137-141)
I20260812 06:19:42.689970 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000030 (ops 142-146)
I20260812 06:19:42.690037 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000031 (ops 147-151)
I20260812 06:19:42.690078 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000032 (ops 152-156)
I20260812 06:19:42.690136 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000033 (ops 157-160)
I20260812 06:19:42.690176 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000034 (ops 161-165)
I20260812 06:19:42.690213 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000035 (ops 166-170)
I20260812 06:19:42.690253 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000036 (ops 171-174)
I20260812 06:19:42.690291 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000037 (ops 175-179)
I20260812 06:19:42.690344 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000038 (ops 180-184)
I20260812 06:19:42.690383 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000039 (ops 185-189)
I20260812 06:19:42.719069 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: LogGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:42.719551 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6): 482 bytes on disk
I20260812 06:19:42.720116 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: UndoDeltaBlockGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.720804 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=3.181125
I20260812 06:19:42.737067 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.016s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4651,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:42.737561 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling LogGCOp(00c76ba3837644b4846ce3716c7629b6): free 12017954 bytes of WAL
I20260812 06:19:42.737804 20386 log_reader.cc:385] T 00c76ba3837644b4846ce3716c7629b6: removed 1 log segments from log reader
I20260812 06:19:42.737850 20386 log.cc:1079] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/00c76ba3837644b4846ce3716c7629b6/wal-000000040 (ops 190-194)
I20260812 06:19:42.740406 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: LogGCOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:42.740785 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=2.188937
I20260812 06:19:42.752344 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3729,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.752974 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6): perf score=1.000000
I20260812 06:19:42.895803 20227 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.123s	user 1.918s	sys 0.109s
I20260812 06:19:42.980477 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: MajorDeltaCompactionOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.227s	user 0.158s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938773,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":690,"lbm_read_time_us":18355,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38169,"lbm_writes_lt_1ms":743,"mutex_wait_us":97,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18048,"thread_start_us":113,"threads_started":1,"update_count":3500}
I20260812 06:19:42.981267 20473 maintenance_manager.cc:419] P 2ced33255b5849b7a9f9c7f6dd9965d9: Scheduling FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6): perf score=10.126437
I20260812 06:19:42.996497 20227 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.100s	user 0.003s	sys 0.000s
I20260812 06:19:42.997175 20227 tablet_server.cc:179] TabletServer@127.19.192.193:0 shutting down...
I20260812 06:19:43.023159 20386 maintenance_manager.cc:643] P 2ced33255b5849b7a9f9c7f6dd9965d9: FlushDeltaMemStoresOp(00c76ba3837644b4846ce3716c7629b6) complete. Timing: real 0.042s	user 0.037s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17842,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.023808 20227 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:43.024231 20227 tablet_replica.cc:333] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9: stopping tablet replica
I20260812 06:19:43.024482 20227 raft_consensus.cc:2243] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:43.024755 20227 raft_consensus.cc:2272] T 00c76ba3837644b4846ce3716c7629b6 P 2ced33255b5849b7a9f9c7f6dd9965d9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:43.039857 20227 tablet_server.cc:196] TabletServer@127.19.192.193:0 shutdown complete.
I20260812 06:19:43.044965 20227 master.cc:562] Master@127.19.192.254:42205 shutting down...
I20260812 06:19:43.048606 20227 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:43.048815 20227 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:43.048913 20227 tablet_replica.cc:333] T 00000000000000000000000000000000 P 67247dc4c6534d628a41a7fe9406b648: stopping tablet replica
I20260812 06:19:43.061422 20227 master.cc:584] Master@127.19.192.254:42205 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5684 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:43.156425 20227 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.192.254:33423
I20260812 06:19:43.156879 20227 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:43.159189 20525 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:43.159245 20523 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:43.159189 20527 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:43.159412 20227 server_base.cc:1061] running on GCE node
I20260812 06:19:43.159632 20227 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:43.159698 20227 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:43.159725 20227 hybrid_clock.cc:648] HybridClock initialized: now 1786515583159724 us; error 0 us; skew 500 ppm
I20260812 06:19:43.160662 20227 webserver.cc:533] Webserver started at http://127.19.192.254:44545/ using document root <none> and password file <none>
I20260812 06:19:43.160892 20227 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:43.160969 20227 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:43.161053 20227 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:43.161485 20227 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/master-0-root/instance:
uuid: "0ed5a685acba44b58a21cfd6d55d6978"
format_stamp: "Formatted at 2026-08-12 06:19:43 on dist-test-slave-twwt"
I20260812 06:19:43.163311 20227 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:43.164484 20536 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:43.164814 20227 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:43.164917 20227 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/master-0-root
uuid: "0ed5a685acba44b58a21cfd6d55d6978"
format_stamp: "Formatted at 2026-08-12 06:19:43 on dist-test-slave-twwt"
I20260812 06:19:43.165015 20227 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:43.171460 20227 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:43.171916 20227 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:43.177454 20227 rpc_server.cc:307] RPC server started. Bound to: 127.19.192.254:33423
I20260812 06:19:43.180265 20614 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.192.254:33423 every 8 connection(s)
I20260812 06:19:43.192581 20615 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:43.194929 20615 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978: Bootstrap starting.
I20260812 06:19:43.195840 20615 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:43.197023 20615 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978: No bootstrap required, opened a new log
I20260812 06:19:43.197474 20615 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0ed5a685acba44b58a21cfd6d55d6978" member_type: VOTER }
I20260812 06:19:43.197592 20615 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:43.197645 20615 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0ed5a685acba44b58a21cfd6d55d6978, State: Initialized, Role: FOLLOWER
I20260812 06:19:43.197845 20615 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [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: "0ed5a685acba44b58a21cfd6d55d6978" member_type: VOTER }
I20260812 06:19:43.197963 20615 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:43.198014 20615 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:43.198072 20615 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:43.198822 20615 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0ed5a685acba44b58a21cfd6d55d6978" member_type: VOTER }
I20260812 06:19:43.198987 20615 leader_election.cc:304] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [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: 0ed5a685acba44b58a21cfd6d55d6978; no voters: 
I20260812 06:19:43.199208 20615 leader_election.cc:290] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:43.199404 20618 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:43.199643 20618 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 1 LEADER]: Becoming Leader. State: Replica: 0ed5a685acba44b58a21cfd6d55d6978, State: Running, Role: LEADER
I20260812 06:19:43.199738 20615 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:43.199822 20618 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [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: "0ed5a685acba44b58a21cfd6d55d6978" member_type: VOTER }
I20260812 06:19:43.200326 20619 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0ed5a685acba44b58a21cfd6d55d6978" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0ed5a685acba44b58a21cfd6d55d6978" member_type: VOTER } }
I20260812 06:19:43.200431 20619 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:43.200384 20620 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0ed5a685acba44b58a21cfd6d55d6978. Latest consensus state: current_term: 1 leader_uuid: "0ed5a685acba44b58a21cfd6d55d6978" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0ed5a685acba44b58a21cfd6d55d6978" member_type: VOTER } }
I20260812 06:19:43.200583 20620 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:43.200848 20626 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:43.201699 20626 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:43.201956 20227 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:43.203715 20626 catalog_manager.cc:1383] Generated new cluster ID: cebfa652644b4a0eae0f2c6a76f52e8d
I20260812 06:19:43.203778 20626 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:43.208527 20626 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:43.209098 20626 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:43.215047 20626 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978: Generated new TSK 0
I20260812 06:19:43.215251 20626 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:43.218327 20227 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:43.220389 20647 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:43.220398 20649 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:43.220544 20227 server_base.cc:1061] running on GCE node
W20260812 06:19:43.220539 20646 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:43.220880 20227 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:43.220928 20227 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:43.220943 20227 hybrid_clock.cc:648] HybridClock initialized: now 1786515583220944 us; error 0 us; skew 500 ppm
I20260812 06:19:43.221827 20227 webserver.cc:533] Webserver started at http://127.19.192.193:41263/ using document root <none> and password file <none>
I20260812 06:19:43.222010 20227 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:43.222087 20227 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:43.222177 20227 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:43.222711 20227 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/instance:
uuid: "4d4e99611e074eca9b58d6d2cbe081db"
format_stamp: "Formatted at 2026-08-12 06:19:43 on dist-test-slave-twwt"
I20260812 06:19:43.224287 20227 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:43.225266 20663 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:43.225504 20227 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:43.225597 20227 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root
uuid: "4d4e99611e074eca9b58d6d2cbe081db"
format_stamp: "Formatted at 2026-08-12 06:19:43 on dist-test-slave-twwt"
I20260812 06:19:43.225689 20227 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:43.241153 20227 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:43.241597 20227 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:43.241945 20227 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:43.242447 20227 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:43.242508 20227 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:43.242573 20227 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:43.242658 20227 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:43.247066 20227 rpc_server.cc:307] RPC server started. Bound to: 127.19.192.193:44629
I20260812 06:19:43.247104 20773 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.192.193:44629 every 8 connection(s)
I20260812 06:19:43.258455 20774 heartbeater.cc:344] Connected to a master server at 127.19.192.254:33423
I20260812 06:19:43.258598 20774 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:43.258919 20774 heartbeater.cc:507] Master 127.19.192.254:33423 requested a full tablet report, sending...
I20260812 06:19:43.259733 20564 ts_manager.cc:194] Registered new tserver with Master: 4d4e99611e074eca9b58d6d2cbe081db (127.19.192.193:44629)
I20260812 06:19:43.259815 20227 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012280513s
I20260812 06:19:43.260716 20564 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40854
I20260812 06:19:43.268015 20564 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40870:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:43.277486 20716 tablet_service.cc:1511] Processing CreateTablet for tablet e8c79b8c5d0d41e2a6e33231d60660a4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ebda0ce8a37c4092971dc3a380e82f94]), partition=
I20260812 06:19:43.277755 20716 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e8c79b8c5d0d41e2a6e33231d60660a4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:43.279846 20793 tablet_bootstrap.cc:492] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Bootstrap starting.
I20260812 06:19:43.280735 20793 tablet_bootstrap.cc:654] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:43.281855 20793 tablet_bootstrap.cc:492] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: No bootstrap required, opened a new log
I20260812 06:19:43.281937 20793 ts_tablet_manager.cc:1403] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:43.282361 20793 raft_consensus.cc:359] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d4e99611e074eca9b58d6d2cbe081db" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 44629 } }
I20260812 06:19:43.282450 20793 raft_consensus.cc:385] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:43.282471 20793 raft_consensus.cc:740] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4d4e99611e074eca9b58d6d2cbe081db, State: Initialized, Role: FOLLOWER
I20260812 06:19:43.282624 20793 consensus_queue.cc:260] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [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: "4d4e99611e074eca9b58d6d2cbe081db" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 44629 } }
I20260812 06:19:43.282819 20793 raft_consensus.cc:399] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:43.282847 20793 raft_consensus.cc:493] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:43.282879 20793 raft_consensus.cc:3060] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:43.283679 20793 raft_consensus.cc:515] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d4e99611e074eca9b58d6d2cbe081db" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 44629 } }
I20260812 06:19:43.283842 20793 leader_election.cc:304] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [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: 4d4e99611e074eca9b58d6d2cbe081db; no voters: 
I20260812 06:19:43.284082 20793 leader_election.cc:290] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:43.284353 20796 raft_consensus.cc:2804] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:43.284613 20796 raft_consensus.cc:697] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 1 LEADER]: Becoming Leader. State: Replica: 4d4e99611e074eca9b58d6d2cbe081db, State: Running, Role: LEADER
I20260812 06:19:43.284677 20774 heartbeater.cc:499] Master 127.19.192.254:33423 was elected leader, sending a full tablet report...
I20260812 06:19:43.284770 20796 consensus_queue.cc:237] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [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: "4d4e99611e074eca9b58d6d2cbe081db" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 44629 } }
I20260812 06:19:43.284670 20793 ts_tablet_manager.cc:1434] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:43.286230 20564 catalog_manager.cc:5719] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db reported cstate change: term changed from 0 to 1, leader changed from <none> to 4d4e99611e074eca9b58d6d2cbe081db (127.19.192.193). New cstate: current_term: 1 leader_uuid: "4d4e99611e074eca9b58d6d2cbe081db" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d4e99611e074eca9b58d6d2cbe081db" member_type: VOTER last_known_addr { host: "127.19.192.193" port: 44629 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:43.349305 20227 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.011s	sys 0.012s
I20260812 06:19:43.498064 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=19.054940
I20260812 06:19:43.655145 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.157s	user 0.115s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":969,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39395,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:43.655902 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): free 20743880 bytes of WAL
I20260812 06:19:43.656183 20671 log_reader.cc:385] T e8c79b8c5d0d41e2a6e33231d60660a4: removed 2 log segments from log reader
I20260812 06:19:43.656245 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000001 (ops 1-6)
I20260812 06:19:43.656278 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000002 (ops 7-11)
I20260812 06:19:43.660643 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:43.661164 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:43.680637 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.019s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.681334 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): 16411392 bytes on disk
I20260812 06:19:43.681789 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) 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:19:43.682296 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:43.826385 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.144s	user 0.112s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":11307,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23727,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":332,"threads_started":5,"update_count":2000}
I20260812 06:19:43.827150 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:43.881954 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.055s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21912,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.882581 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:43.894519 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4326,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.895120 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:44.067984 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.173s	user 0.123s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":12131,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32216,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28544,"update_count":2500}
I20260812 06:19:44.068670 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:44.124011 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.055s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23539,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.124687 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:44.292433 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.168s	user 0.102s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":669,"lbm_read_time_us":13595,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24263,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:19:44.293160 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:44.343382 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.050s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21627,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.343924 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:44.356433 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.357019 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:44.551463 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.194s	user 0.136s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":415,"lbm_read_time_us":13855,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29267,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:44.552099 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:44.602949 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.051s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22473,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.603505 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:44.616406 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.616900 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:44.796856 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.180s	user 0.129s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":473,"lbm_read_time_us":12183,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35207,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:44.797618 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:44.847632 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.050s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.848219 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:44.860926 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.861711 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:44.888959 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1379,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1729,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:44.889603 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): free 108082389 bytes of WAL
I20260812 06:19:44.889855 20671 log_reader.cc:385] T e8c79b8c5d0d41e2a6e33231d60660a4: removed 11 log segments from log reader
I20260812 06:19:44.889904 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000003 (ops 12-16)
I20260812 06:19:44.889932 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000004 (ops 17-20)
I20260812 06:19:44.889994 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000005 (ops 21-25)
I20260812 06:19:44.890040 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000006 (ops 26-30)
I20260812 06:19:44.890076 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000007 (ops 31-35)
I20260812 06:19:44.890151 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000008 (ops 36-40)
I20260812 06:19:44.890187 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000009 (ops 41-44)
I20260812 06:19:44.890223 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000010 (ops 45-49)
I20260812 06:19:44.890262 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000011 (ops 50-54)
I20260812 06:19:44.890300 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000012 (ops 55-58)
I20260812 06:19:44.890338 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000013 (ops 59-63)
I20260812 06:19:44.916043 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:44.916478 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): 448 bytes on disk
I20260812 06:19:44.916970 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.917455 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=3.181125
I20260812 06:19:44.940945 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.023s	user 0.007s	sys 0.014s Metrics: {"bytes_written":4882122,"delete_count":0,"lbm_write_time_us":5174,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:19:44.941504 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:44.951352 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3510,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:19:44.951849 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:45.206570 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.255s	user 0.169s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":300,"lbm_read_time_us":16872,"lbm_reads_lt_1ms":774,"lbm_write_time_us":47147,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:19:45.207345 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:45.280992 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.073s	user 0.043s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":32568,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.281580 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:45.300956 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.019s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.301442 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:45.487159 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.186s	user 0.132s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1738,"lbm_read_time_us":12589,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33465,"lbm_writes_lt_1ms":543,"mutex_wait_us":1137,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:45.488001 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:45.554267 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.066s	user 0.029s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23844,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.554935 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:45.566430 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.567106 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:45.759441 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.192s	user 0.136s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1238,"lbm_read_time_us":14328,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30006,"lbm_writes_lt_1ms":543,"mutex_wait_us":375,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":50304,"update_count":2500}
I20260812 06:19:45.760164 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:45.813726 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.053s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20483,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.814320 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:45.837625 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.023s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.838268 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:46.038652 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.200s	user 0.133s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":13293,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34284,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:46.039496 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:46.093815 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.054s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22166,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.094539 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=3.181125
I20260812 06:19:46.124400 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.030s	user 0.016s	sys 0.012s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7489,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:46.125067 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:46.135870 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.136379 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:46.333225 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.197s	user 0.132s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1064,"lbm_read_time_us":15228,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32521,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":3000}
I20260812 06:19:46.333968 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:46.394209 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.060s	user 0.030s	sys 0.026s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":21764,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.394918 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:46.406244 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.406759 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:46.450835 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.044s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1388,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1523,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:46.451545 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): free 124257256 bytes of WAL
I20260812 06:19:46.451784 20671 log_reader.cc:385] T e8c79b8c5d0d41e2a6e33231d60660a4: removed 12 log segments from log reader
I20260812 06:19:46.451850 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000014 (ops 64-68)
I20260812 06:19:46.451915 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000015 (ops 69-73)
I20260812 06:19:46.451972 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000016 (ops 74-78)
I20260812 06:19:46.452015 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000017 (ops 79-83)
I20260812 06:19:46.452054 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000018 (ops 84-88)
I20260812 06:19:46.452091 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000019 (ops 89-93)
I20260812 06:19:46.452129 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000020 (ops 94-98)
I20260812 06:19:46.452167 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000021 (ops 99-102)
I20260812 06:19:46.452205 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000022 (ops 103-107)
I20260812 06:19:46.452244 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000023 (ops 108-112)
I20260812 06:19:46.452282 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000024 (ops 113-117)
I20260812 06:19:46.452320 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000025 (ops 118-122)
I20260812 06:19:46.482759 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.031s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:46.483177 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:46.500027 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.017s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.500537 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): 447 bytes on disk
I20260812 06:19:46.500969 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.501550 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:46.512930 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.513669 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:46.748004 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.234s	user 0.151s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979755,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":360,"lbm_read_time_us":15880,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41091,"lbm_writes_lt_1ms":743,"mutex_wait_us":437,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:19:46.748715 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=18.063937
I20260812 06:19:46.816453 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.067s	user 0.050s	sys 0.015s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":30846,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.817288 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:46.833880 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.834599 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:47.010984 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.176s	user 0.127s	sys 0.049s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":168,"lbm_read_time_us":12975,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34920,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":3000}
I20260812 06:19:47.011735 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:47.064097 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.052s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21336,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.064841 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:47.076295 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.077128 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:47.260704 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.183s	user 0.116s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1813,"lbm_read_time_us":12012,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34339,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:47.261417 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:47.324774 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.062s	user 0.031s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25849,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.325304 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:47.337482 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4259,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.338052 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:47.520637 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.182s	user 0.129s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1085,"lbm_read_time_us":13445,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31834,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:19:47.521304 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:47.586058 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.065s	user 0.025s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29262,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.586802 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:47.603598 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.017s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.604108 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:47.788558 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.184s	user 0.094s	sys 0.089s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1219,"lbm_read_time_us":14015,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33121,"lbm_writes_lt_1ms":543,"mutex_wait_us":349,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:47.789124 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:47.858171 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.069s	user 0.039s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26777,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.858880 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:47.869884 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.870378 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:47.915742 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushMRSOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.045s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1603,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1458,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:47.916527 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): free 112239525 bytes of WAL
I20260812 06:19:47.916766 20671 log_reader.cc:385] T e8c79b8c5d0d41e2a6e33231d60660a4: removed 11 log segments from log reader
I20260812 06:19:47.916813 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000026 (ops 123-127)
I20260812 06:19:47.916843 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000027 (ops 128-132)
I20260812 06:19:47.916903 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000028 (ops 133-137)
I20260812 06:19:47.916944 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000029 (ops 138-142)
I20260812 06:19:47.916987 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000030 (ops 143-147)
I20260812 06:19:47.917026 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000031 (ops 148-152)
I20260812 06:19:47.917068 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000032 (ops 153-156)
I20260812 06:19:47.917106 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000033 (ops 157-161)
I20260812 06:19:47.917143 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000034 (ops 162-166)
I20260812 06:19:47.917181 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000035 (ops 167-171)
I20260812 06:19:47.917218 20671 log.cc:1079] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: Deleting log segment in path: /tmp/dist-test-taskMta1C8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515577460590-20227-0/minicluster-data/ts-0-root/wals/e8c79b8c5d0d41e2a6e33231d60660a4/wal-000000036 (ops 172-176)
I20260812 06:19:47.943393 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: LogGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:47.943845 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=3.181125
I20260812 06:19:47.968427 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.024s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7148,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:47.968987 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:47.979440 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.979933 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4): 447 bytes on disk
I20260812 06:19:47.980394 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: UndoDeltaBlockGCOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.981333 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:48.230532 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.249s	user 0.191s	sys 0.048s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4301,"dirs.run_cpu_time_us":486,"dirs.run_wall_time_us":2714,"lbm_read_time_us":19812,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42158,"lbm_writes_lt_1ms":743,"mutex_wait_us":3036,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":3500}
I20260812 06:19:48.232551 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=15.087375
I20260812 06:19:48.286352 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.053s	user 0.031s	sys 0.018s Metrics: {"bytes_written":16738094,"delete_count":0,"lbm_write_time_us":22848,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2040}
I20260812 06:19:48.287382 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=2.188937
I20260812 06:19:48.303953 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5994,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:48.304441 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:48.498236 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.194s	user 0.113s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774681,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1024,"lbm_read_time_us":11545,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32552,"lbm_writes_lt_1ms":543,"mutex_wait_us":418,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:48.499059 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=14.095187
I20260812 06:19:48.554824 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: FlushDeltaMemStoresOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.056s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22117,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.555361 20777 maintenance_manager.cc:419] P 4d4e99611e074eca9b58d6d2cbe081db: Scheduling MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4): perf score=1.000000
I20260812 06:19:48.569756 20227 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.220s	user 1.850s	sys 0.219s
I20260812 06:19:48.636574 20227 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.066s	user 0.001s	sys 0.000s
I20260812 06:19:48.637164 20227 tablet_server.cc:179] TabletServer@127.19.192.193:0 shutting down...
I20260812 06:19:48.682930 20671 maintenance_manager.cc:643] P 4d4e99611e074eca9b58d6d2cbe081db: MajorDeltaCompactionOp(e8c79b8c5d0d41e2a6e33231d60660a4) complete. Timing: real 0.127s	user 0.092s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":878,"lbm_read_time_us":11148,"lbm_reads_lt_1ms":459,"lbm_write_time_us":21747,"lbm_writes_lt_1ms":443,"mutex_wait_us":170,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":58752,"update_count":2000}
I20260812 06:19:48.683755 20227 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:48.684087 20227 tablet_replica.cc:333] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db: stopping tablet replica
I20260812 06:19:48.684273 20227 raft_consensus.cc:2243] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:48.684484 20227 raft_consensus.cc:2272] T e8c79b8c5d0d41e2a6e33231d60660a4 P 4d4e99611e074eca9b58d6d2cbe081db [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:48.689296 20227 tablet_server.cc:196] TabletServer@127.19.192.193:0 shutdown complete.
I20260812 06:19:48.721628 20227 master.cc:562] Master@127.19.192.254:33423 shutting down...
I20260812 06:19:48.724915 20227 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:48.725143 20227 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:48.725234 20227 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0ed5a685acba44b58a21cfd6d55d6978: stopping tablet replica
I20260812 06:19:48.738162 20227 master.cc:584] Master@127.19.192.254:33423 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5682 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11368 ms total)

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