[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:32.975786 26260 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.165.62:39865
I20260812 06:17:32.976730 26260 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:32.977311 26260 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:32.983121 26270 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:32.983162 26267 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:32.983363 26260 server_base.cc:1061] running on GCE node
W20260812 06:17:32.983381 26268 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:32.983860 26260 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:32.983955 26260 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:32.983985 26260 hybrid_clock.cc:648] HybridClock initialized: now 1786515452983983 us; error 0 us; skew 500 ppm
I20260812 06:17:32.985504 26260 webserver.cc:533] Webserver started at http://127.25.165.62:41829/ using document root <none> and password file <none>
I20260812 06:17:32.986016 26260 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:32.986073 26260 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:32.986253 26260 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:32.987705 26260 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/master-0-root/instance:
uuid: "59f8b1e4889c49fa86435dd3d1b8f712"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-tc2s"
I20260812 06:17:32.990809 26260 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:32.992622 26283 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.993512 26260 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:32.993610 26260 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/master-0-root
uuid: "59f8b1e4889c49fa86435dd3d1b8f712"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-tc2s"
I20260812 06:17:32.993686 26260 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:33.006102 26260 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:33.006584 26260 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:33.006716 26260 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:33.013451 26260 rpc_server.cc:307] RPC server started. Bound to: 127.25.165.62:39865
I20260812 06:17:33.013458 26382 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.165.62:39865 every 8 connection(s)
I20260812 06:17:33.015513 26383 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:33.020548 26383 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712: Bootstrap starting.
I20260812 06:17:33.022735 26383 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:33.023563 26383 log.cc:826] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:33.025008 26383 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712: No bootstrap required, opened a new log
I20260812 06:17:33.027612 26383 raft_consensus.cc:359] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "59f8b1e4889c49fa86435dd3d1b8f712" member_type: VOTER }
I20260812 06:17:33.027760 26383 raft_consensus.cc:385] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:33.027825 26383 raft_consensus.cc:740] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 59f8b1e4889c49fa86435dd3d1b8f712, State: Initialized, Role: FOLLOWER
I20260812 06:17:33.028347 26383 consensus_queue.cc:260] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [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: "59f8b1e4889c49fa86435dd3d1b8f712" member_type: VOTER }
I20260812 06:17:33.028491 26383 raft_consensus.cc:399] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:33.028555 26383 raft_consensus.cc:493] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:33.028671 26383 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:33.029345 26383 raft_consensus.cc:515] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "59f8b1e4889c49fa86435dd3d1b8f712" member_type: VOTER }
I20260812 06:17:33.029738 26383 leader_election.cc:304] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [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: 59f8b1e4889c49fa86435dd3d1b8f712; no voters: 
I20260812 06:17:33.030030 26383 leader_election.cc:290] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:33.030117 26387 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:33.030309 26387 raft_consensus.cc:697] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 1 LEADER]: Becoming Leader. State: Replica: 59f8b1e4889c49fa86435dd3d1b8f712, State: Running, Role: LEADER
I20260812 06:17:33.030714 26387 consensus_queue.cc:237] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [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: "59f8b1e4889c49fa86435dd3d1b8f712" member_type: VOTER }
I20260812 06:17:33.030877 26383 sys_catalog.cc:565] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:33.032335 26391 sys_catalog.cc:455] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 59f8b1e4889c49fa86435dd3d1b8f712. Latest consensus state: current_term: 1 leader_uuid: "59f8b1e4889c49fa86435dd3d1b8f712" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "59f8b1e4889c49fa86435dd3d1b8f712" member_type: VOTER } }
I20260812 06:17:33.032379 26389 sys_catalog.cc:455] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "59f8b1e4889c49fa86435dd3d1b8f712" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "59f8b1e4889c49fa86435dd3d1b8f712" member_type: VOTER } }
I20260812 06:17:33.032461 26391 sys_catalog.cc:458] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:33.032472 26389 sys_catalog.cc:458] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:33.032797 26412 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:33.033015 26260 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:33.034945 26412 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:33.039100 26412 catalog_manager.cc:1383] Generated new cluster ID: 3138a867dced4020a800ca012ab1b9ec
I20260812 06:17:33.039160 26412 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:33.066103 26412 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:33.066931 26412 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:33.074322 26412 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712: Generated new TSK 0
I20260812 06:17:33.074862 26412 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:33.097533 26260 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:33.100005 26436 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:33.100092 26433 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:33.100139 26432 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:33.100355 26260 server_base.cc:1061] running on GCE node
I20260812 06:17:33.100518 26260 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:33.100561 26260 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:33.100589 26260 hybrid_clock.cc:648] HybridClock initialized: now 1786515453100588 us; error 0 us; skew 500 ppm
I20260812 06:17:33.101466 26260 webserver.cc:533] Webserver started at http://127.25.165.1:45983/ using document root <none> and password file <none>
I20260812 06:17:33.101624 26260 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:33.101680 26260 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:33.101754 26260 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:33.102190 26260 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/instance:
uuid: "65c6d6cf12384d7995fcc1352b58e03f"
format_stamp: "Formatted at 2026-08-12 06:17:33 on dist-test-slave-tc2s"
I20260812 06:17:33.103924 26260 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:33.104904 26447 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:33.105145 26260 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:33.105209 26260 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root
uuid: "65c6d6cf12384d7995fcc1352b58e03f"
format_stamp: "Formatted at 2026-08-12 06:17:33 on dist-test-slave-tc2s"
I20260812 06:17:33.105270 26260 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:33.110739 26260 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:33.111095 26260 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:33.111498 26260 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:33.112219 26260 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:33.112268 26260 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:33.112317 26260 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:33.112349 26260 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:33.118399 26260 rpc_server.cc:307] RPC server started. Bound to: 127.25.165.1:42753
I20260812 06:17:33.118439 26550 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.165.1:42753 every 8 connection(s)
I20260812 06:17:33.130232 26552 heartbeater.cc:344] Connected to a master server at 127.25.165.62:39865
I20260812 06:17:33.130447 26552 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:33.130827 26552 heartbeater.cc:507] Master 127.25.165.62:39865 requested a full tablet report, sending...
I20260812 06:17:33.132225 26309 ts_manager.cc:194] Registered new tserver with Master: 65c6d6cf12384d7995fcc1352b58e03f (127.25.165.1:42753)
I20260812 06:17:33.132330 26260 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01335873s
I20260812 06:17:33.133792 26309 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51630
I20260812 06:17:33.141610 26309 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51646:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:33.154827 26498 tablet_service.cc:1511] Processing CreateTablet for tablet 0e6804e3096a4e5bb563fc3da3e8d417 (DEFAULT_TABLE table=heavy-update-compaction-test [id=465ee458fbf94862ac3ded541ea06142]), partition=
I20260812 06:17:33.155246 26498 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0e6804e3096a4e5bb563fc3da3e8d417. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:33.157405 26574 tablet_bootstrap.cc:492] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Bootstrap starting.
I20260812 06:17:33.158501 26574 tablet_bootstrap.cc:654] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:33.160024 26574 tablet_bootstrap.cc:492] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: No bootstrap required, opened a new log
I20260812 06:17:33.160126 26574 ts_tablet_manager.cc:1403] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:33.160614 26574 raft_consensus.cc:359] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65c6d6cf12384d7995fcc1352b58e03f" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 42753 } }
I20260812 06:17:33.160725 26574 raft_consensus.cc:385] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:33.160763 26574 raft_consensus.cc:740] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 65c6d6cf12384d7995fcc1352b58e03f, State: Initialized, Role: FOLLOWER
I20260812 06:17:33.160887 26574 consensus_queue.cc:260] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [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: "65c6d6cf12384d7995fcc1352b58e03f" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 42753 } }
I20260812 06:17:33.160967 26574 raft_consensus.cc:399] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:33.161008 26574 raft_consensus.cc:493] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:33.161053 26574 raft_consensus.cc:3060] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:33.161971 26574 raft_consensus.cc:515] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65c6d6cf12384d7995fcc1352b58e03f" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 42753 } }
I20260812 06:17:33.162118 26574 leader_election.cc:304] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [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: 65c6d6cf12384d7995fcc1352b58e03f; no voters: 
I20260812 06:17:33.162310 26574 leader_election.cc:290] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:33.162575 26577 raft_consensus.cc:2804] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:33.162645 26574 ts_tablet_manager.cc:1434] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:33.163007 26577 raft_consensus.cc:697] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 1 LEADER]: Becoming Leader. State: Replica: 65c6d6cf12384d7995fcc1352b58e03f, State: Running, Role: LEADER
I20260812 06:17:33.163024 26552 heartbeater.cc:499] Master 127.25.165.62:39865 was elected leader, sending a full tablet report...
I20260812 06:17:33.163388 26577 consensus_queue.cc:237] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [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: "65c6d6cf12384d7995fcc1352b58e03f" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 42753 } }
I20260812 06:17:33.165649 26309 catalog_manager.cc:5719] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f reported cstate change: term changed from 0 to 1, leader changed from <none> to 65c6d6cf12384d7995fcc1352b58e03f (127.25.165.1). New cstate: current_term: 1 leader_uuid: "65c6d6cf12384d7995fcc1352b58e03f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65c6d6cf12384d7995fcc1352b58e03f" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 42753 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:33.232960 26260 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.018s	sys 0.008s
I20260812 06:17:33.369541 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=19.054940
I20260812 06:17:33.567059 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.197s	user 0.142s	sys 0.050s Metrics: {"bytes_written":16409902,"cfile_init":1,"compiler_manager_pool.queue_time_us":472,"delete_count":0,"dirs.queue_time_us":39,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":887,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47380,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":172,"threads_started":1,"update_count":2000}
I20260812 06:17:33.568655 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417): free 20743880 bytes of WAL
I20260812 06:17:33.569105 26455 log_reader.cc:385] T 0e6804e3096a4e5bb563fc3da3e8d417: removed 2 log segments from log reader
I20260812 06:17:33.569244 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000001 (ops 1-6)
I20260812 06:17:33.569353 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000002 (ops 7-11)
I20260812 06:17:33.574931 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:33.575404 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417): 16411397 bytes on disk
I20260812 06:17:33.576692 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.577217 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:33.608235 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.031s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:17:33.609758 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:33.621640 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4616,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.622121 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:33.811290 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.189s	user 0.127s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":602,"lbm_read_time_us":13727,"lbm_reads_lt_1ms":669,"lbm_write_time_us":31017,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":287,"threads_started":5,"update_count":3000}
I20260812 06:17:33.811825 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:33.866957 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.055s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19289,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.867465 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:33.877065 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.877418 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:34.037328 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.160s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":12359,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27182,"lbm_writes_lt_1ms":543,"mutex_wait_us":254,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:34.037856 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=11.118625
I20260812 06:17:34.074306 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.036s	user 0.020s	sys 0.016s Metrics: {"bytes_written":13127976,"delete_count":0,"lbm_write_time_us":12975,"lbm_writes_lt_1ms":323,"reinsert_count":0,"update_count":1600}
I20260812 06:17:34.074813 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:34.088176 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692409,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.088634 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:34.233198 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.144s	user 0.086s	sys 0.057s Metrics: {"cfile_cache_miss":442,"cfile_cache_miss_bytes":21082513,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":9952,"lbm_reads_lt_1ms":474,"lbm_write_time_us":23609,"lbm_writes_lt_1ms":453,"mutex_wait_us":83,"peak_mem_usage":51099678,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2050}
I20260812 06:17:34.233829 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=10.126437
I20260812 06:17:34.268026 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.034s	user 0.022s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14367,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.268445 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:34.281427 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5011,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.282174 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:34.398113 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.116s	user 0.099s	sys 0.016s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262024,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":92,"lbm_read_time_us":6977,"lbm_reads_lt_1ms":454,"lbm_write_time_us":22746,"lbm_writes_lt_1ms":433,"mutex_wait_us":16,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":1950}
I20260812 06:17:34.398651 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=10.126437
I20260812 06:17:34.439570 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.041s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17257,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.440099 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:34.450867 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.451277 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:34.571031 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.120s	user 0.084s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":136,"lbm_read_time_us":8145,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23957,"lbm_writes_lt_1ms":443,"mutex_wait_us":18,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:34.573710 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=11.118625
I20260812 06:17:34.615778 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.042s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15603,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:34.616240 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:34.626628 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3719,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.627101 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:34.762392 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.135s	user 0.087s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":9860,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20993,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:17:34.762848 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=10.126437
I20260812 06:17:34.803187 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.040s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13291,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.803762 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:34.818416 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.014s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.818817 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:34.850265 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1051,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1973,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:34.850998 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417): free 124710295 bytes of WAL
I20260812 06:17:34.851207 26455 log_reader.cc:385] T 0e6804e3096a4e5bb563fc3da3e8d417: removed 12 log segments from log reader
I20260812 06:17:34.851253 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000003 (ops 12-16)
I20260812 06:17:34.851282 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000004 (ops 17-21)
I20260812 06:17:34.851313 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000005 (ops 22-26)
I20260812 06:17:34.851338 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000006 (ops 27-31)
I20260812 06:17:34.851370 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000007 (ops 32-36)
I20260812 06:17:34.851401 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000008 (ops 37-41)
I20260812 06:17:34.851433 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000009 (ops 42-46)
I20260812 06:17:34.851465 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000010 (ops 47-51)
I20260812 06:17:34.851497 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000011 (ops 52-56)
I20260812 06:17:34.851528 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000012 (ops 57-61)
I20260812 06:17:34.851559 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000013 (ops 62-66)
I20260812 06:17:34.851589 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000014 (ops 67-71)
I20260812 06:17:34.873919 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.023s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:34.874322 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417): 482 bytes on disk
I20260812 06:17:34.874742 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417) 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:17:34.875264 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=3.181125
I20260812 06:17:34.896476 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.021s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4442,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:34.896864 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:34.906157 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3577,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.906492 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:35.095201 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.189s	user 0.105s	sys 0.078s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":402,"lbm_read_time_us":13163,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30047,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:17:35.096073 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:35.149488 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.052s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15512,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.149971 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:35.159756 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.160097 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:35.322256 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.162s	user 0.095s	sys 0.064s 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":252,"lbm_read_time_us":11631,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27253,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:17:35.322768 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=11.118625
I20260812 06:17:35.378019 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.055s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":36692,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:35.378499 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:35.389186 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.389621 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:35.406373 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3243,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:35.406926 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:35.580596 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.173s	user 0.109s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":850,"lbm_read_time_us":11577,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26332,"lbm_writes_lt_1ms":543,"mutex_wait_us":264,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:35.581060 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:35.625795 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.045s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22462,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.626284 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:35.639258 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.639818 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:35.810341 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.170s	user 0.106s	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":1833,"lbm_read_time_us":9062,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27208,"lbm_writes_lt_1ms":543,"mutex_wait_us":1304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:17:35.810851 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:35.864106 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.053s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21117,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.864574 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:35.874070 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.874665 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:36.025498 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.151s	user 0.108s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":139,"lbm_read_time_us":10496,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30120,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:36.026051 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=11.118625
I20260812 06:17:36.056969 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.031s	user 0.015s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13538,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:36.057430 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:36.069502 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.070129 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:36.188758 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.118s	user 0.081s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":960,"lbm_read_time_us":7412,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22659,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:17:36.189339 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=10.126437
I20260812 06:17:36.222690 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.033s	user 0.024s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12265,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.223250 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:36.233672 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.234244 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:36.262176 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":163,"dirs.run_wall_time_us":1300,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1645,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:36.262861 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417): free 121006445 bytes of WAL
I20260812 06:17:36.263075 26455 log_reader.cc:385] T 0e6804e3096a4e5bb563fc3da3e8d417: removed 12 log segments from log reader
I20260812 06:17:36.263134 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000015 (ops 72-76)
I20260812 06:17:36.263172 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000016 (ops 77-81)
I20260812 06:17:36.263202 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000017 (ops 82-86)
I20260812 06:17:36.263236 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000018 (ops 87-90)
I20260812 06:17:36.263268 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000019 (ops 91-95)
I20260812 06:17:36.263296 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000020 (ops 96-100)
I20260812 06:17:36.263324 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000021 (ops 101-105)
I20260812 06:17:36.263350 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000022 (ops 106-110)
I20260812 06:17:36.263382 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000023 (ops 111-115)
I20260812 06:17:36.263413 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000024 (ops 116-120)
I20260812 06:17:36.263440 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000025 (ops 121-125)
I20260812 06:17:36.263466 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000026 (ops 126-130)
I20260812 06:17:36.289197 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:36.289618 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417): 472 bytes on disk
I20260812 06:17:36.290079 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.290649 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=3.181125
I20260812 06:17:36.302937 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:36.303285 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:36.312079 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.009s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3445,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.312431 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:36.468528 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.156s	user 0.099s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":592,"lbm_read_time_us":11890,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29929,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8192,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:36.469393 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:36.517400 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.048s	user 0.032s	sys 0.007s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":18526,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.517835 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:36.527727 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.528326 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:36.675787 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.147s	user 0.118s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1089,"lbm_read_time_us":10816,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26514,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:36.676488 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=12.110812
I20260812 06:17:36.722981 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.046s	user 0.022s	sys 0.020s Metrics: {"bytes_written":13907423,"delete_count":0,"lbm_write_time_us":19833,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":341,"reinsert_count":0,"update_count":1695}
I20260812 06:17:36.723469 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.196750
I20260812 06:17:36.734321 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.011s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2912934,"delete_count":0,"lbm_write_time_us":2676,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:17:36.734788 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:36.747310 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4775,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.747692 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:36.909924 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.162s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774762,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":136,"lbm_read_time_us":11952,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28035,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:36.910543 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:36.966670 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.056s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21859,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.967208 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:36.981757 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.014s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.982249 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:37.156412 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.174s	user 0.119s	sys 0.053s 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":957,"lbm_read_time_us":12972,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30081,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:37.156935 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:37.216420 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.059s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20255,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.216914 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:37.226902 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.227288 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:37.410957 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.184s	user 0.132s	sys 0.040s 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":445,"lbm_read_time_us":11732,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30478,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:17:37.411535 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=14.095187
I20260812 06:17:37.469444 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.055s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17337,"lbm_writes_lt_1ms":403,"mutex_wait_us":1,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.469998 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:37.484635 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.485090 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:37.647192 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.162s	user 0.115s	sys 0.045s 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":213,"lbm_read_time_us":12328,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27234,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2500}
I20260812 06:17:37.647750 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=11.118625
I20260812 06:17:37.677121 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.029s	user 0.016s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12404,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:37.677887 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=2.188937
I20260812 06:17:37.691504 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5226,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.692005 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:37.718164 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushMRSOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.026s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1143,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1498,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:37.718850 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417): free 136728518 bytes of WAL
I20260812 06:17:37.719086 26455 log_reader.cc:385] T 0e6804e3096a4e5bb563fc3da3e8d417: removed 13 log segments from log reader
I20260812 06:17:37.719149 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000027 (ops 131-135)
I20260812 06:17:37.719247 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000028 (ops 136-140)
I20260812 06:17:37.719317 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000029 (ops 141-145)
I20260812 06:17:37.719370 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000030 (ops 146-150)
I20260812 06:17:37.719440 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000031 (ops 151-155)
I20260812 06:17:37.719497 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000032 (ops 156-160)
I20260812 06:17:37.719544 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000033 (ops 161-165)
I20260812 06:17:37.719595 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000034 (ops 166-170)
I20260812 06:17:37.719641 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000035 (ops 171-175)
I20260812 06:17:37.719683 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000036 (ops 176-180)
I20260812 06:17:37.719751 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000037 (ops 181-185)
I20260812 06:17:37.719810 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000038 (ops 186-190)
I20260812 06:17:37.719852 26455 log.cc:1079] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/0e6804e3096a4e5bb563fc3da3e8d417/wal-000000039 (ops 191-195)
I20260812 06:17:37.745846 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: LogGCOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:37.746649 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417): 492 bytes on disk
I20260812 06:17:37.747157 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: UndoDeltaBlockGCOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:37.747695 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=4.173312
I20260812 06:17:37.762058 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":5907729,"delete_count":0,"lbm_write_time_us":5925,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:17:37.762472 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.196750
I20260812 06:17:37.769421 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: FlushDeltaMemStoresOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":2207,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:17:37.769954 26553 maintenance_manager.cc:419] P 65c6d6cf12384d7995fcc1352b58e03f: Scheduling MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417): perf score=1.000000
I20260812 06:17:37.850639 26260 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.618s	user 1.663s	sys 0.134s
I20260812 06:17:37.937837 26260 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.001s	sys 0.000s
I20260812 06:17:37.938441 26260 tablet_server.cc:179] TabletServer@127.25.165.1:0 shutting down...
I20260812 06:17:37.947985 26455 maintenance_manager.cc:643] P 65c6d6cf12384d7995fcc1352b58e03f: MajorDeltaCompactionOp(0e6804e3096a4e5bb563fc3da3e8d417) complete. Timing: real 0.178s	user 0.094s	sys 0.081s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877289,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":470,"lbm_read_time_us":13321,"lbm_reads_lt_1ms":670,"lbm_write_time_us":27967,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10752,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:17:37.948704 26260 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:37.949085 26260 tablet_replica.cc:333] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f: stopping tablet replica
I20260812 06:17:37.949345 26260 raft_consensus.cc:2243] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.949586 26260 raft_consensus.cc:2272] T 0e6804e3096a4e5bb563fc3da3e8d417 P 65c6d6cf12384d7995fcc1352b58e03f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.965015 26260 tablet_server.cc:196] TabletServer@127.25.165.1:0 shutdown complete.
I20260812 06:17:37.995384 26260 master.cc:562] Master@127.25.165.62:39865 shutting down...
I20260812 06:17:37.998942 26260 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.999086 26260 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.999138 26260 tablet_replica.cc:333] T 00000000000000000000000000000000 P 59f8b1e4889c49fa86435dd3d1b8f712: stopping tablet replica
I20260812 06:17:38.010998 26260 master.cc:584] Master@127.25.165.62:39865 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5104 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:38.091038 26260 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.165.62:39877
I20260812 06:17:38.091410 26260 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:38.093226 26617 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:38.093302 26618 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:38.093354 26260 server_base.cc:1061] running on GCE node
W20260812 06:17:38.093369 26623 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:38.093554 26260 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:38.093596 26260 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:38.093616 26260 hybrid_clock.cc:648] HybridClock initialized: now 1786515458093615 us; error 0 us; skew 500 ppm
I20260812 06:17:38.094396 26260 webserver.cc:533] Webserver started at http://127.25.165.62:34191/ using document root <none> and password file <none>
I20260812 06:17:38.094548 26260 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:38.094591 26260 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:38.094666 26260 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:38.095031 26260 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/master-0-root/instance:
uuid: "6c1d24e4d35241779c7a1a5d486ffce6"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-tc2s"
I20260812 06:17:38.096429 26260 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:38.097254 26629 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.097473 26260 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:38.097543 26260 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/master-0-root
uuid: "6c1d24e4d35241779c7a1a5d486ffce6"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-tc2s"
I20260812 06:17:38.097609 26260 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:38.114385 26260 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.114672 26260 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.118475 26260 rpc_server.cc:307] RPC server started. Bound to: 127.25.165.62:39877
I20260812 06:17:38.123359 26732 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.165.62:39877 every 8 connection(s)
I20260812 06:17:38.123793 26736 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:38.125414 26736 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6: Bootstrap starting.
I20260812 06:17:38.126204 26736 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.127096 26736 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6: No bootstrap required, opened a new log
I20260812 06:17:38.127457 26736 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c1d24e4d35241779c7a1a5d486ffce6" member_type: VOTER }
I20260812 06:17:38.127539 26736 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.127569 26736 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6c1d24e4d35241779c7a1a5d486ffce6, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.127699 26736 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [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: "6c1d24e4d35241779c7a1a5d486ffce6" member_type: VOTER }
I20260812 06:17:38.127770 26736 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.127805 26736 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.127854 26736 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.128530 26736 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c1d24e4d35241779c7a1a5d486ffce6" member_type: VOTER }
I20260812 06:17:38.128652 26736 leader_election.cc:304] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [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: 6c1d24e4d35241779c7a1a5d486ffce6; no voters: 
I20260812 06:17:38.128813 26736 leader_election.cc:290] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.128911 26740 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.129106 26740 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 1 LEADER]: Becoming Leader. State: Replica: 6c1d24e4d35241779c7a1a5d486ffce6, State: Running, Role: LEADER
I20260812 06:17:38.129217 26736 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:38.129231 26740 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [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: "6c1d24e4d35241779c7a1a5d486ffce6" member_type: VOTER }
I20260812 06:17:38.129680 26741 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6c1d24e4d35241779c7a1a5d486ffce6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c1d24e4d35241779c7a1a5d486ffce6" member_type: VOTER } }
I20260812 06:17:38.129715 26744 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6c1d24e4d35241779c7a1a5d486ffce6. Latest consensus state: current_term: 1 leader_uuid: "6c1d24e4d35241779c7a1a5d486ffce6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c1d24e4d35241779c7a1a5d486ffce6" member_type: VOTER } }
I20260812 06:17:38.129772 26741 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.129796 26744 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.130033 26749 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:38.130868 26749 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:38.131075 26260 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:38.132475 26749 catalog_manager.cc:1383] Generated new cluster ID: 9590a926cd3b41d98ed9af4356b107e2
I20260812 06:17:38.132527 26749 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:38.161018 26749 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:38.161490 26749 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:38.169162 26749 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6: Generated new TSK 0
I20260812 06:17:38.169294 26749 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:38.195264 26260 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:38.197078 26774 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:38.197131 26771 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:38.197175 26260 server_base.cc:1061] running on GCE node
W20260812 06:17:38.197245 26769 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:38.197530 26260 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:38.197571 26260 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:38.197585 26260 hybrid_clock.cc:648] HybridClock initialized: now 1786515458197586 us; error 0 us; skew 500 ppm
I20260812 06:17:38.198369 26260 webserver.cc:533] Webserver started at http://127.25.165.1:39463/ using document root <none> and password file <none>
I20260812 06:17:38.198516 26260 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:38.198575 26260 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:38.198652 26260 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:38.199041 26260 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/instance:
uuid: "e0b2704a627141deace8e6cfce659a00"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-tc2s"
I20260812 06:17:38.200424 26260 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:38.201265 26781 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.201464 26260 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:38.201527 26260 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root
uuid: "e0b2704a627141deace8e6cfce659a00"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-tc2s"
I20260812 06:17:38.201593 26260 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:38.214941 26260 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.215230 26260 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.215487 26260 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:38.215889 26260 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:38.215932 26260 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.215976 26260 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:38.216006 26260 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.219976 26260 rpc_server.cc:307] RPC server started. Bound to: 127.25.165.1:43731
I20260812 06:17:38.220371 26905 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.165.1:43731 every 8 connection(s)
I20260812 06:17:38.226747 26906 heartbeater.cc:344] Connected to a master server at 127.25.165.62:39877
I20260812 06:17:38.226840 26906 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:38.227036 26906 heartbeater.cc:507] Master 127.25.165.62:39877 requested a full tablet report, sending...
I20260812 06:17:38.227630 26661 ts_manager.cc:194] Registered new tserver with Master: e0b2704a627141deace8e6cfce659a00 (127.25.165.1:43731)
I20260812 06:17:38.228168 26260 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007659809s
I20260812 06:17:38.228323 26661 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38546
I20260812 06:17:38.234220 26661 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38558:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:38.241801 26841 tablet_service.cc:1511] Processing CreateTablet for tablet caa8e64ff6334b50b8a70723c1efdb48 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0f1285d359534dc2bab1a46fe21b2bb1]), partition=
I20260812 06:17:38.242057 26841 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet caa8e64ff6334b50b8a70723c1efdb48. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:38.243817 26938 tablet_bootstrap.cc:492] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Bootstrap starting.
I20260812 06:17:38.244741 26938 tablet_bootstrap.cc:654] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.245673 26938 tablet_bootstrap.cc:492] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: No bootstrap required, opened a new log
I20260812 06:17:38.245741 26938 ts_tablet_manager.cc:1403] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:38.246119 26938 raft_consensus.cc:359] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0b2704a627141deace8e6cfce659a00" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 43731 } }
I20260812 06:17:38.246197 26938 raft_consensus.cc:385] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.246222 26938 raft_consensus.cc:740] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e0b2704a627141deace8e6cfce659a00, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.246315 26938 consensus_queue.cc:260] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [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: "e0b2704a627141deace8e6cfce659a00" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 43731 } }
I20260812 06:17:38.246368 26938 raft_consensus.cc:399] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.246394 26938 raft_consensus.cc:493] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.246434 26938 raft_consensus.cc:3060] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.247071 26938 raft_consensus.cc:515] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0b2704a627141deace8e6cfce659a00" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 43731 } }
I20260812 06:17:38.247193 26938 leader_election.cc:304] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [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: e0b2704a627141deace8e6cfce659a00; no voters: 
I20260812 06:17:38.247373 26938 leader_election.cc:290] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.247480 26942 raft_consensus.cc:2804] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.247649 26942 raft_consensus.cc:697] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 1 LEADER]: Becoming Leader. State: Replica: e0b2704a627141deace8e6cfce659a00, State: Running, Role: LEADER
I20260812 06:17:38.247714 26938 ts_tablet_manager.cc:1434] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:38.247774 26942 consensus_queue.cc:237] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [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: "e0b2704a627141deace8e6cfce659a00" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 43731 } }
I20260812 06:17:38.247851 26906 heartbeater.cc:499] Master 127.25.165.62:39877 was elected leader, sending a full tablet report...
I20260812 06:17:38.248936 26661 catalog_manager.cc:5719] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 reported cstate change: term changed from 0 to 1, leader changed from <none> to e0b2704a627141deace8e6cfce659a00 (127.25.165.1). New cstate: current_term: 1 leader_uuid: "e0b2704a627141deace8e6cfce659a00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0b2704a627141deace8e6cfce659a00" member_type: VOTER last_known_addr { host: "127.25.165.1" port: 43731 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:38.302634 26260 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.017s	sys 0.004s
I20260812 06:17:38.471052 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=23.023690
I20260812 06:17:38.631564 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.160s	user 0.089s	sys 0.065s Metrics: {"bytes_written":14317671,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":890,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43162,"lbm_writes_lt_1ms":906,"mutex_wait_us":156,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1745}
I20260812 06:17:38.632071 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48): 20513815 bytes on disk
I20260812 06:17:38.632427 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.632792 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.196750
I20260812 06:17:38.646128 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.013s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3077038,"delete_count":0,"lbm_write_time_us":2876,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:17:38.646478 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling LogGCOp(caa8e64ff6334b50b8a70723c1efdb48): free 20743880 bytes of WAL
I20260812 06:17:38.646641 26792 log_reader.cc:385] T caa8e64ff6334b50b8a70723c1efdb48: removed 2 log segments from log reader
I20260812 06:17:38.646682 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000001 (ops 1-6)
I20260812 06:17:38.646719 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000002 (ops 7-11)
I20260812 06:17:38.650389 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: LogGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.004s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:17:38.650629 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.196750
I20260812 06:17:38.658245 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.007s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":2827,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:38.658653 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:38.826038 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.167s	user 0.113s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815759,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":651,"lbm_read_time_us":13015,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26614,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":325,"threads_started":5,"update_count":2500}
I20260812 06:17:38.826551 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:38.869673 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.043s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409920,"delete_count":0,"lbm_write_time_us":19400,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.870101 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:39.016010 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.146s	user 0.088s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713171,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":164,"lbm_read_time_us":10859,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22041,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:17:39.016498 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:39.071080 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.054s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17509,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.071607 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:39.086124 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.086584 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:39.264456 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.178s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":745,"lbm_read_time_us":12442,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26279,"lbm_writes_lt_1ms":543,"mutex_wait_us":231,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:17:39.264921 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:39.327987 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.063s	user 0.038s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23438,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.328506 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:39.343461 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.343950 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:39.527993 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.184s	user 0.098s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":12586,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28348,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:17:39.528548 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:39.573213 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.045s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.573733 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:39.588953 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.589437 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:39.767756 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.178s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":11051,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27170,"lbm_writes_lt_1ms":543,"mutex_wait_us":238,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:39.768224 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:39.813412 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.045s	user 0.013s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20552,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.813931 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:39.827188 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.827787 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:39.851863 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.024s	user 0.022s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1144,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1265,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:39.852454 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling LogGCOp(caa8e64ff6334b50b8a70723c1efdb48): free 120553398 bytes of WAL
I20260812 06:17:39.852680 26792 log_reader.cc:385] T caa8e64ff6334b50b8a70723c1efdb48: removed 12 log segments from log reader
I20260812 06:17:39.852727 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000003 (ops 12-16)
I20260812 06:17:39.852766 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000004 (ops 17-20)
I20260812 06:17:39.852798 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000005 (ops 21-25)
I20260812 06:17:39.852831 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000006 (ops 26-30)
I20260812 06:17:39.852862 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000007 (ops 31-35)
I20260812 06:17:39.852891 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000008 (ops 36-40)
I20260812 06:17:39.852922 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000009 (ops 41-44)
I20260812 06:17:39.852952 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000010 (ops 45-49)
I20260812 06:17:39.852986 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000011 (ops 50-54)
I20260812 06:17:39.853016 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000012 (ops 55-59)
I20260812 06:17:39.853045 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000013 (ops 60-64)
I20260812 06:17:39.853075 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000014 (ops 65-69)
I20260812 06:17:39.877983 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: LogGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:39.878401 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48): 472 bytes on disk
I20260812 06:17:39.879029 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:17:39.879527 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=3.181125
I20260812 06:17:39.898912 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.019s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:39.899276 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:39.912410 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.912818 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:40.136538 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.224s	user 0.133s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":225,"lbm_read_time_us":14894,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35091,"lbm_writes_lt_1ms":743,"mutex_wait_us":24,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":47232,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:17:40.137039 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=18.063937
I20260812 06:17:40.190562 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.053s	user 0.026s	sys 0.023s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":23213,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:40.190989 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:40.349213 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.158s	user 0.120s	sys 0.036s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815569,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1011,"lbm_read_time_us":11310,"lbm_reads_lt_1ms":563,"lbm_write_time_us":27350,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:40.349912 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:40.402632 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.052s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18235,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.403151 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:40.417791 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.418257 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:40.601485 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.183s	user 0.108s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":13460,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27163,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:40.602041 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:40.655944 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.054s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.656471 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:40.666344 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.666788 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:40.840775 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.174s	user 0.115s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":12008,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28316,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:40.841388 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=11.118625
I20260812 06:17:40.878151 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.037s	user 0.021s	sys 0.014s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15198,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1550}
I20260812 06:17:40.878746 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:40.892912 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.014s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3845,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:40.893426 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:41.019120 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.126s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":544,"lbm_read_time_us":7164,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24409,"lbm_writes_lt_1ms":443,"mutex_wait_us":253,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.019722 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=10.126437
I20260812 06:17:41.056051 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16335,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:17:41.056540 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:41.067205 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3713,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.067680 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:41.190326 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.123s	user 0.083s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":8891,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23710,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:17:41.190861 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=10.126437
I20260812 06:17:41.235292 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.044s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14610,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.235782 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:41.245417 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3701,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.245858 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:41.277262 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1136,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1865,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:41.278010 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling LogGCOp(caa8e64ff6334b50b8a70723c1efdb48): free 120553380 bytes of WAL
I20260812 06:17:41.278226 26792 log_reader.cc:385] T caa8e64ff6334b50b8a70723c1efdb48: removed 12 log segments from log reader
I20260812 06:17:41.278275 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000015 (ops 70-74)
I20260812 06:17:41.278312 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000016 (ops 75-78)
I20260812 06:17:41.278344 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000017 (ops 79-83)
I20260812 06:17:41.278378 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000018 (ops 84-88)
I20260812 06:17:41.278409 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000019 (ops 89-93)
I20260812 06:17:41.278440 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000020 (ops 94-98)
I20260812 06:17:41.278470 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000021 (ops 99-103)
I20260812 06:17:41.278501 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000022 (ops 104-108)
I20260812 06:17:41.278532 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000023 (ops 109-113)
I20260812 06:17:41.278560 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000024 (ops 114-118)
I20260812 06:17:41.278590 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000025 (ops 119-122)
I20260812 06:17:41.278620 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000026 (ops 123-127)
I20260812 06:17:41.298594 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: LogGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.020s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:41.299109 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:41.317049 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5838,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.317471 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48): 448 bytes on disk
I20260812 06:17:41.317873 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.318379 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:41.327860 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.009s	user 0.002s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.328217 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:41.499776 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.171s	user 0.138s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":912,"lbm_read_time_us":13596,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32102,"lbm_writes_lt_1ms":643,"mutex_wait_us":513,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:17:41.500330 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:41.544756 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.044s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19168,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.545244 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:41.558396 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.558912 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:41.706669 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.148s	user 0.112s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":780,"lbm_read_time_us":9419,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27995,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:17:41.707186 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:41.749330 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.042s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18304,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.749924 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:41.895355 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.145s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1057,"lbm_read_time_us":10814,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23049,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:17:41.895910 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:41.950160 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.054s	user 0.018s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25296,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.950668 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:41.962899 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4418,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.966310 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:42.139132 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.173s	user 0.128s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":826,"lbm_read_time_us":11122,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26778,"lbm_writes_lt_1ms":543,"mutex_wait_us":17,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:17:42.139604 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:42.188620 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.049s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21558,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.189168 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:42.199692 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.200254 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:42.353565 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.153s	user 0.112s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1120,"lbm_read_time_us":9948,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28335,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:42.354172 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:42.400681 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.046s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19826,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.401152 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:42.416531 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.417309 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:42.560624 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.143s	user 0.101s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":9594,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30035,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:42.561223 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=11.118625
I20260812 06:17:42.596002 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.035s	user 0.009s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14963,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:42.596556 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:42.620586 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.024s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4845,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.621029 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:42.631923 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.632447 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:42.665568 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushMRSOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1142,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1681,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:42.666304 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling LogGCOp(caa8e64ff6334b50b8a70723c1efdb48): free 133024641 bytes of WAL
I20260812 06:17:42.666522 26792 log_reader.cc:385] T caa8e64ff6334b50b8a70723c1efdb48: removed 13 log segments from log reader
I20260812 06:17:42.666567 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000027 (ops 128-132)
I20260812 06:17:42.666599 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000028 (ops 133-137)
I20260812 06:17:42.666630 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000029 (ops 138-143)
I20260812 06:17:42.666656 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000030 (ops 144-148)
I20260812 06:17:42.666687 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000031 (ops 149-153)
I20260812 06:17:42.666718 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000032 (ops 154-158)
I20260812 06:17:42.666749 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000033 (ops 159-162)
I20260812 06:17:42.666780 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000034 (ops 163-167)
I20260812 06:17:42.666811 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000035 (ops 168-172)
I20260812 06:17:42.666850 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000036 (ops 173-177)
I20260812 06:17:42.666883 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000037 (ops 178-182)
I20260812 06:17:42.666914 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000038 (ops 183-186)
I20260812 06:17:42.666947 26792 log.cc:1079] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: Deleting log segment in path: /tmp/dist-test-task6WcBBT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452965528-26260-0/minicluster-data/ts-0-root/wals/caa8e64ff6334b50b8a70723c1efdb48/wal-000000039 (ops 187-191)
I20260812 06:17:42.688648 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: LogGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.022s	user 0.004s	sys 0.016s Metrics: {}
I20260812 06:17:42.689056 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48): 482 bytes on disk
I20260812 06:17:42.689446 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: UndoDeltaBlockGCOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.690066 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=3.181125
I20260812 06:17:42.701395 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:42.701757 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=2.188937
I20260812 06:17:42.714458 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4857,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.714867 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:42.877497 26260 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.575s	user 1.629s	sys 0.198s
I20260812 06:17:42.890753 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.176s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020846,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":11899,"lbm_reads_lt_1ms":771,"lbm_write_time_us":37429,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":3500}
I20260812 06:17:42.891273 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=14.095187
I20260812 06:17:42.942015 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: FlushDeltaMemStoresOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.051s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23578,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:42.942682 26908 maintenance_manager.cc:419] P e0b2704a627141deace8e6cfce659a00: Scheduling MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48): perf score=1.000000
I20260812 06:17:42.961174 26260 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.083s	user 0.000s	sys 0.000s
I20260812 06:17:42.961643 26260 tablet_server.cc:179] TabletServer@127.25.165.1:0 shutting down...
I20260812 06:17:43.053807 26792 maintenance_manager.cc:643] P e0b2704a627141deace8e6cfce659a00: MajorDeltaCompactionOp(caa8e64ff6334b50b8a70723c1efdb48) complete. Timing: real 0.111s	user 0.094s	sys 0.016s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":335,"lbm_read_time_us":9041,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22251,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:17:43.054472 26260 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:43.054729 26260 tablet_replica.cc:333] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00: stopping tablet replica
I20260812 06:17:43.054855 26260 raft_consensus.cc:2243] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:43.055038 26260 raft_consensus.cc:2272] T caa8e64ff6334b50b8a70723c1efdb48 P e0b2704a627141deace8e6cfce659a00 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:43.068853 26260 tablet_server.cc:196] TabletServer@127.25.165.1:0 shutdown complete.
I20260812 06:17:43.093291 26260 master.cc:562] Master@127.25.165.62:39877 shutting down...
I20260812 06:17:43.096402 26260 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:43.096566 26260 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:43.096635 26260 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6c1d24e4d35241779c7a1a5d486ffce6: stopping tablet replica
I20260812 06:17:43.108760 26260 master.cc:584] Master@127.25.165.62:39877 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5099 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10205 ms total)

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