[==========] 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.409423 23655 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.25.254:36457
I20260812 06:17:32.410462 23655 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.411082 23655 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:32.417263 23663 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:32.417297 23667 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:32.417485 23655 server_base.cc:1061] running on GCE node
W20260812 06:17:32.417587 23665 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.418089 23655 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:32.418215 23655 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.418273 23655 hybrid_clock.cc:648] HybridClock initialized: now 1786515452418271 us; error 0 us; skew 500 ppm
I20260812 06:17:32.420081 23655 webserver.cc:533] Webserver started at http://127.23.25.254:46579/ using document root <none> and password file <none>
I20260812 06:17:32.420678 23655 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:32.420768 23655 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:32.421028 23655 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:32.422942 23655 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/master-0-root/instance:
uuid: "667ae285384a4ae1a3caeef91740010d"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-07c2"
I20260812 06:17:32.426407 23655 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:32.428500 23673 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.429467 23655 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:32.429596 23655 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/master-0-root
uuid: "667ae285384a4ae1a3caeef91740010d"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-07c2"
I20260812 06:17:32.429729 23655 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-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:32.454232 23655 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:32.454944 23655 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:32.455137 23655 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:32.462954 23735 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.25.254:36457 every 8 connection(s)
I20260812 06:17:32.462955 23655 rpc_server.cc:307] RPC server started. Bound to: 127.23.25.254:36457
I20260812 06:17:32.465413 23737 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:32.470986 23737 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d: Bootstrap starting.
I20260812 06:17:32.473402 23737 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:32.474357 23737 log.cc:826] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:32.476225 23737 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d: No bootstrap required, opened a new log
I20260812 06:17:32.479023 23737 raft_consensus.cc:359] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "667ae285384a4ae1a3caeef91740010d" member_type: VOTER }
I20260812 06:17:32.479219 23737 raft_consensus.cc:385] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:32.479331 23737 raft_consensus.cc:740] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 667ae285384a4ae1a3caeef91740010d, State: Initialized, Role: FOLLOWER
I20260812 06:17:32.479950 23737 consensus_queue.cc:260] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [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: "667ae285384a4ae1a3caeef91740010d" member_type: VOTER }
I20260812 06:17:32.480118 23737 raft_consensus.cc:399] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:32.480194 23737 raft_consensus.cc:493] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:32.480383 23737 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:32.481225 23737 raft_consensus.cc:515] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "667ae285384a4ae1a3caeef91740010d" member_type: VOTER }
I20260812 06:17:32.481688 23737 leader_election.cc:304] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [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: 667ae285384a4ae1a3caeef91740010d; no voters: 
I20260812 06:17:32.482059 23737 leader_election.cc:290] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:32.482225 23741 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:32.482470 23741 raft_consensus.cc:697] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 1 LEADER]: Becoming Leader. State: Replica: 667ae285384a4ae1a3caeef91740010d, State: Running, Role: LEADER
I20260812 06:17:32.482918 23741 consensus_queue.cc:237] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [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: "667ae285384a4ae1a3caeef91740010d" member_type: VOTER }
I20260812 06:17:32.483091 23737 sys_catalog.cc:565] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:32.484907 23743 sys_catalog.cc:455] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 667ae285384a4ae1a3caeef91740010d. Latest consensus state: current_term: 1 leader_uuid: "667ae285384a4ae1a3caeef91740010d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "667ae285384a4ae1a3caeef91740010d" member_type: VOTER } }
I20260812 06:17:32.484961 23742 sys_catalog.cc:455] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "667ae285384a4ae1a3caeef91740010d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "667ae285384a4ae1a3caeef91740010d" member_type: VOTER } }
I20260812 06:17:32.485042 23743 sys_catalog.cc:458] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:32.485042 23742 sys_catalog.cc:458] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:32.485610 23759 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:32.485790 23655 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:32.487903 23759 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:32.492885 23759 catalog_manager.cc:1383] Generated new cluster ID: fe2740af7ec741b7ae8af1fab3471616
I20260812 06:17:32.492969 23759 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:32.540405 23759 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:32.541401 23759 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:32.550974 23759 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d: Generated new TSK 0
I20260812 06:17:32.551692 23759 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:32.615082 23655 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:32.617911 23769 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.618083 23655 server_base.cc:1061] running on GCE node
W20260812 06:17:32.618062 23770 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:32.618247 23772 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:32.618517 23655 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:32.618593 23655 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.618621 23655 hybrid_clock.cc:648] HybridClock initialized: now 1786515452618620 us; error 0 us; skew 500 ppm
I20260812 06:17:32.619632 23655 webserver.cc:533] Webserver started at http://127.23.25.193:46621/ using document root <none> and password file <none>
I20260812 06:17:32.619824 23655 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:32.619896 23655 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:32.619976 23655 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:32.620419 23655 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/instance:
uuid: "ec1785e553bd46119ffde588a94887d4"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-07c2"
I20260812 06:17:32.621941 23655 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:32.622933 23777 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.623171 23655 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:32.623243 23655 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root
uuid: "ec1785e553bd46119ffde588a94887d4"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-07c2"
I20260812 06:17:32.623351 23655 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-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:32.662861 23655 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:32.663390 23655 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:32.663869 23655 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:32.664722 23655 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:32.664773 23655 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.664841 23655 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:32.664881 23655 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.669588 23655 rpc_server.cc:307] RPC server started. Bound to: 127.23.25.193:34117
I20260812 06:17:32.669924 23854 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.25.193:34117 every 8 connection(s)
I20260812 06:17:32.678445 23855 heartbeater.cc:344] Connected to a master server at 127.23.25.254:36457
I20260812 06:17:32.678658 23855 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:32.679029 23855 heartbeater.cc:507] Master 127.23.25.254:36457 requested a full tablet report, sending...
I20260812 06:17:32.680413 23694 ts_manager.cc:194] Registered new tserver with Master: ec1785e553bd46119ffde588a94887d4 (127.23.25.193:34117)
I20260812 06:17:32.680554 23655 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010160367s
I20260812 06:17:32.681530 23694 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47150
I20260812 06:17:32.689793 23694 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47152:
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:32.702025 23813 tablet_service.cc:1511] Processing CreateTablet for tablet 7d51a356f5e04bd9920f6ea8ea310e1a (DEFAULT_TABLE table=heavy-update-compaction-test [id=b860b93ba7be438ca2d5c79c080e2cef]), partition=
I20260812 06:17:32.702453 23813 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7d51a356f5e04bd9920f6ea8ea310e1a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:32.704968 23872 tablet_bootstrap.cc:492] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Bootstrap starting.
I20260812 06:17:32.705864 23872 tablet_bootstrap.cc:654] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:32.707084 23872 tablet_bootstrap.cc:492] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: No bootstrap required, opened a new log
I20260812 06:17:32.707228 23872 ts_tablet_manager.cc:1403] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:32.707665 23872 raft_consensus.cc:359] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec1785e553bd46119ffde588a94887d4" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 34117 } }
I20260812 06:17:32.707787 23872 raft_consensus.cc:385] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:32.707855 23872 raft_consensus.cc:740] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ec1785e553bd46119ffde588a94887d4, State: Initialized, Role: FOLLOWER
I20260812 06:17:32.708035 23872 consensus_queue.cc:260] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [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: "ec1785e553bd46119ffde588a94887d4" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 34117 } }
I20260812 06:17:32.708156 23872 raft_consensus.cc:399] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:32.708209 23872 raft_consensus.cc:493] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:32.708273 23872 raft_consensus.cc:3060] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:32.709007 23872 raft_consensus.cc:515] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec1785e553bd46119ffde588a94887d4" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 34117 } }
I20260812 06:17:32.709172 23872 leader_election.cc:304] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [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: ec1785e553bd46119ffde588a94887d4; no voters: 
I20260812 06:17:32.709393 23872 leader_election.cc:290] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:32.709586 23874 raft_consensus.cc:2804] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:32.709770 23872 ts_tablet_manager.cc:1434] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:32.709978 23855 heartbeater.cc:499] Master 127.23.25.254:36457 was elected leader, sending a full tablet report...
I20260812 06:17:32.710399 23874 raft_consensus.cc:697] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 1 LEADER]: Becoming Leader. State: Replica: ec1785e553bd46119ffde588a94887d4, State: Running, Role: LEADER
I20260812 06:17:32.710748 23874 consensus_queue.cc:237] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [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: "ec1785e553bd46119ffde588a94887d4" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 34117 } }
I20260812 06:17:32.713591 23694 catalog_manager.cc:5719] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 reported cstate change: term changed from 0 to 1, leader changed from <none> to ec1785e553bd46119ffde588a94887d4 (127.23.25.193). New cstate: current_term: 1 leader_uuid: "ec1785e553bd46119ffde588a94887d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec1785e553bd46119ffde588a94887d4" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 34117 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:32.776373 23655 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.018s	sys 0.008s
I20260812 06:17:32.920826 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=19.054940
I20260812 06:17:33.122448 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.201s	user 0.153s	sys 0.044s Metrics: {"bytes_written":16409902,"cfile_init":1,"compiler_manager_pool.queue_time_us":602,"delete_count":0,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1044,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":52738,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":856,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":194,"threads_started":1,"update_count":2000}
I20260812 06:17:33.123896 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): free 20743880 bytes of WAL
I20260812 06:17:33.124367 23784 log_reader.cc:385] T 7d51a356f5e04bd9920f6ea8ea310e1a: removed 2 log segments from log reader
I20260812 06:17:33.124509 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000001 (ops 1-6)
I20260812 06:17:33.124627 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000002 (ops 7-11)
I20260812 06:17:33.130260 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:33.130841 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): 16411392 bytes on disk
I20260812 06:17:33.131824 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.132794 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=3.181125
I20260812 06:17:33.145750 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4348804,"delete_count":0,"lbm_write_time_us":4873,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:17:33.146209 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:33.333448 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.187s	user 0.137s	sys 0.039s Metrics: {"cfile_cache_miss":538,"cfile_cache_miss_bytes":25020834,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":866,"lbm_read_time_us":11474,"lbm_reads_lt_1ms":566,"lbm_write_time_us":30239,"lbm_writes_lt_1ms":549,"peak_mem_usage":63362110,"reinsert_count":0,"thread_start_us":383,"threads_started":5,"update_count":2530}
I20260812 06:17:33.334127 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=14.095187
I20260812 06:17:33.382898 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.049s	user 0.033s	sys 0.008s Metrics: {"bytes_written":16163762,"delete_count":0,"lbm_write_time_us":19954,"lbm_writes_lt_1ms":397,"reinsert_count":0,"update_count":1970}
I20260812 06:17:33.383499 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:33.408017 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.024s	user 0.008s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.408620 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:33.579046 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.170s	user 0.109s	sys 0.061s Metrics: {"cfile_cache_miss":526,"cfile_cache_miss_bytes":24528549,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":767,"lbm_read_time_us":14324,"lbm_reads_lt_1ms":566,"lbm_write_time_us":28457,"lbm_writes_lt_1ms":537,"mutex_wait_us":400,"peak_mem_usage":61829306,"reinsert_count":0,"spinlock_wait_cycles":561024,"update_count":2470}
I20260812 06:17:33.579550 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:33.618854 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.039s	user 0.018s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14303,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.620298 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:33.633572 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.634178 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:33.768724 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.134s	user 0.118s	sys 0.015s 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":984,"lbm_read_time_us":8911,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25418,"lbm_writes_lt_1ms":443,"mutex_wait_us":370,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:17:33.769515 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:33.806983 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.037s	user 0.009s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15733,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.807603 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:33.824079 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.824550 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:33.945047 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.120s	user 0.088s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1212,"lbm_read_time_us":7411,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24133,"lbm_writes_lt_1ms":443,"mutex_wait_us":358,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2000}
I20260812 06:17:33.945751 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:33.989657 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.044s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15891,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.990224 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:34.002488 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.003106 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:34.117707 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.114s	user 0.098s	sys 0.016s 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":803,"lbm_read_time_us":7363,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22246,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:17:34.118386 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:34.170665 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.052s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18634,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.171483 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:34.182076 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.182513 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:34.337435 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.155s	user 0.101s	sys 0.048s 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":554,"lbm_read_time_us":9857,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23364,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:17:34.338129 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:34.385110 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.047s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14886,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.385574 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:34.397161 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.397864 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:34.428761 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.031s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1435,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1675,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:34.429528 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): free 120553379 bytes of WAL
I20260812 06:17:34.429761 23784 log_reader.cc:385] T 7d51a356f5e04bd9920f6ea8ea310e1a: removed 12 log segments from log reader
I20260812 06:17:34.429805 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000003 (ops 12-16)
I20260812 06:17:34.429834 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000004 (ops 17-21)
I20260812 06:17:34.429898 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000005 (ops 22-26)
I20260812 06:17:34.429929 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000006 (ops 27-31)
I20260812 06:17:34.429970 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000007 (ops 32-36)
I20260812 06:17:34.430011 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000008 (ops 37-40)
I20260812 06:17:34.430052 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000009 (ops 41-45)
I20260812 06:17:34.430091 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000010 (ops 46-50)
I20260812 06:17:34.430130 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000011 (ops 51-55)
I20260812 06:17:34.430163 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000012 (ops 56-60)
I20260812 06:17:34.430200 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000013 (ops 61-64)
I20260812 06:17:34.430246 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000014 (ops 65-69)
I20260812 06:17:34.456458 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:34.456935 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): 472 bytes on disk
I20260812 06:17:34.457461 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.457932 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=4.173312
I20260812 06:17:34.480406 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.022s	user 0.010s	sys 0.011s Metrics: {"bytes_written":6276942,"delete_count":0,"lbm_write_time_us":6359,"lbm_writes_lt_1ms":156,"mutex_wait_us":72,"reinsert_count":0,"update_count":765}
I20260812 06:17:34.480968 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:34.489599 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":1928327,"delete_count":0,"lbm_write_time_us":2615,"lbm_writes_lt_1ms":50,"reinsert_count":0,"update_count":235}
I20260812 06:17:34.495250 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:34.689260 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.194s	user 0.092s	sys 0.101s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877285,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":236,"lbm_read_time_us":11812,"lbm_reads_lt_1ms":666,"lbm_write_time_us":32040,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":83328,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:34.689963 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=14.095187
I20260812 06:17:34.747471 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.057s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20694,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.748077 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:34.765121 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.765650 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:34.944145 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.178s	user 0.123s	sys 0.055s 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":389,"lbm_read_time_us":12531,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31424,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:34.944823 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=11.118625
I20260812 06:17:34.989984 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.045s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20679,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:34.990439 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:35.014314 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5417,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:35.014798 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:35.025007 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3887,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.025483 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:35.214668 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.189s	user 0.121s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":128,"lbm_read_time_us":12056,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29599,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2500}
I20260812 06:17:35.215366 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=14.095187
I20260812 06:17:35.264132 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.049s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21161,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.264683 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:35.280360 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.015s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.281040 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:35.425661 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.144s	user 0.107s	sys 0.037s 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":858,"lbm_read_time_us":9445,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28666,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:17:35.426328 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:35.469417 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.043s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18035,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.470961 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:35.488387 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.488927 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:35.615504 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.126s	user 0.107s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":933,"lbm_read_time_us":8552,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24763,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:35.617491 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:35.659551 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.042s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18875,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.660099 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:35.671028 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.671581 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:35.797129 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.125s	user 0.113s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":9222,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22018,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31872,"update_count":2000}
I20260812 06:17:35.797834 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:35.847015 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.049s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16457,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.847802 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:35.858749 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.859190 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:35.901681 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.042s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1466,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1636,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":896}
I20260812 06:17:35.902432 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): free 120553337 bytes of WAL
I20260812 06:17:35.902665 23784 log_reader.cc:385] T 7d51a356f5e04bd9920f6ea8ea310e1a: removed 12 log segments from log reader
I20260812 06:17:35.902711 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000015 (ops 70-74)
I20260812 06:17:35.902741 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000016 (ops 75-78)
I20260812 06:17:35.902804 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000017 (ops 79-83)
I20260812 06:17:35.902838 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000018 (ops 84-88)
I20260812 06:17:35.902880 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000019 (ops 89-93)
I20260812 06:17:35.902945 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000020 (ops 94-98)
I20260812 06:17:35.902978 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000021 (ops 99-103)
I20260812 06:17:35.903012 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000022 (ops 104-108)
I20260812 06:17:35.903074 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000023 (ops 109-113)
I20260812 06:17:35.903105 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000024 (ops 114-118)
I20260812 06:17:35.903139 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000025 (ops 119-122)
I20260812 06:17:35.903174 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000026 (ops 123-127)
I20260812 06:17:35.928894 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:35.929390 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=3.181125
I20260812 06:17:35.950256 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.021s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5380,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:35.950765 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): 463 bytes on disk
I20260812 06:17:35.951176 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.951723 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:35.961267 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3590,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:35.961814 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:36.160712 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.199s	user 0.115s	sys 0.083s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1415,"lbm_read_time_us":13327,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35476,"lbm_writes_lt_1ms":643,"mutex_wait_us":359,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29568,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:17:36.161247 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=14.095187
I20260812 06:17:36.222869 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.061s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":31035,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.223465 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:36.367578 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.144s	user 0.103s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":160,"lbm_read_time_us":9409,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25131,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:17:36.368333 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=10.126437
I20260812 06:17:36.405222 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.037s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15144,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.405728 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:36.429888 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.430461 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:36.441141 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4137,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.441768 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:36.632115 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.190s	user 0.140s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":130,"lbm_read_time_us":10426,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29933,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":105088,"update_count":2500}
I20260812 06:17:36.632866 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=14.095187
I20260812 06:17:36.688642 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.056s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23620,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.689167 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:36.701817 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.702330 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:36.854660 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.152s	user 0.120s	sys 0.028s 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":584,"lbm_read_time_us":11296,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30223,"lbm_writes_lt_1ms":543,"mutex_wait_us":264,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:36.855355 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=11.118625
I20260812 06:17:36.899369 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.044s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19902,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:36.900108 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:36.915441 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4584,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.915971 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:36.926625 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.927145 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:37.077001 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.150s	user 0.120s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":529,"lbm_read_time_us":9813,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29773,"lbm_writes_lt_1ms":543,"mutex_wait_us":279,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:17:37.077684 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=11.118625
I20260812 06:17:37.118533 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.041s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16618,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:37.119171 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:37.141803 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.022s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5046,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.142362 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:37.152849 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.153339 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:37.303817 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.150s	user 0.125s	sys 0.021s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":272,"lbm_read_time_us":9926,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29939,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:17:37.304636 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=11.118625
I20260812 06:17:37.338415 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.034s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14094,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:37.338970 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:37.362020 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.023s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.362547 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=2.188937
I20260812 06:17:37.372918 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.373397 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:37.407747 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushMRSOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1347,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1687,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:37.408541 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): free 132571636 bytes of WAL
I20260812 06:17:37.408815 23784 log_reader.cc:385] T 7d51a356f5e04bd9920f6ea8ea310e1a: removed 13 log segments from log reader
I20260812 06:17:37.408883 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000027 (ops 128-132)
I20260812 06:17:37.408936 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000028 (ops 133-137)
I20260812 06:17:37.408993 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000029 (ops 138-142)
I20260812 06:17:37.409035 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000030 (ops 143-147)
I20260812 06:17:37.409071 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000031 (ops 148-152)
I20260812 06:17:37.409116 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000032 (ops 153-156)
I20260812 06:17:37.409160 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000033 (ops 157-161)
I20260812 06:17:37.409197 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000034 (ops 162-166)
I20260812 06:17:37.409235 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000035 (ops 167-170)
I20260812 06:17:37.409272 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000036 (ops 171-175)
I20260812 06:17:37.409310 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000037 (ops 176-180)
I20260812 06:17:37.409345 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000038 (ops 181-185)
I20260812 06:17:37.409382 23784 log.cc:1079] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/7d51a356f5e04bd9920f6ea8ea310e1a/wal-000000039 (ops 186-190)
I20260812 06:17:37.437963 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: LogGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:37.438783 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=4.173312
I20260812 06:17:37.452382 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":5333392,"delete_count":0,"lbm_write_time_us":5313,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:17:37.452841 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a): 482 bytes on disk
I20260812 06:17:37.453244 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: UndoDeltaBlockGCOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:37.453747 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.196750
I20260812 06:17:37.464692 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3883,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:37.465178 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:37.648120 23655 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.872s	user 1.762s	sys 0.134s
I20260812 06:17:37.662452 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.197s	user 0.148s	sys 0.047s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979833,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14787,"lbm_reads_lt_1ms":763,"lbm_write_time_us":41104,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":3500}
I20260812 06:17:37.662964 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=14.095187
I20260812 06:17:37.695067 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: FlushDeltaMemStoresOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":15464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.695544 23857 maintenance_manager.cc:419] P ec1785e553bd46119ffde588a94887d4: Scheduling MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a): perf score=1.000000
I20260812 06:17:37.722779 23655 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.074s	user 0.002s	sys 0.000s
I20260812 06:17:37.723701 23655 tablet_server.cc:179] TabletServer@127.23.25.193:0 shutting down...
I20260812 06:17:37.809396 23784 maintenance_manager.cc:643] P ec1785e553bd46119ffde588a94887d4: MajorDeltaCompactionOp(7d51a356f5e04bd9920f6ea8ea310e1a) complete. Timing: real 0.114s	user 0.086s	sys 0.027s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":334,"lbm_read_time_us":8380,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23584,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.810371 23655 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:37.810778 23655 tablet_replica.cc:333] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4: stopping tablet replica
I20260812 06:17:37.811021 23655 raft_consensus.cc:2243] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.811333 23655 raft_consensus.cc:2272] T 7d51a356f5e04bd9920f6ea8ea310e1a P ec1785e553bd46119ffde588a94887d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.817262 23655 tablet_server.cc:196] TabletServer@127.23.25.193:0 shutdown complete.
I20260812 06:17:37.849601 23655 master.cc:562] Master@127.23.25.254:36457 shutting down...
I20260812 06:17:37.853507 23655 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.853704 23655 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.853803 23655 tablet_replica.cc:333] T 00000000000000000000000000000000 P 667ae285384a4ae1a3caeef91740010d: stopping tablet replica
I20260812 06:17:37.866073 23655 master.cc:584] Master@127.23.25.254:36457 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5543 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:37.963762 23655 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.25.254:37729
I20260812 06:17:37.964190 23655 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:37.966223 23897 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:37.966239 23893 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:37.966354 23895 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:37.966465 23655 server_base.cc:1061] running on GCE node
I20260812 06:17:37.966603 23655 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:37.966667 23655 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:37.966713 23655 hybrid_clock.cc:648] HybridClock initialized: now 1786515457966712 us; error 0 us; skew 500 ppm
I20260812 06:17:37.967590 23655 webserver.cc:533] Webserver started at http://127.23.25.254:34291/ using document root <none> and password file <none>
I20260812 06:17:37.967777 23655 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:37.967842 23655 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:37.967921 23655 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:37.968329 23655 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/master-0-root/instance:
uuid: "5634397e1829441389bfe7e3400c92e2"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-07c2"
I20260812 06:17:37.969933 23655 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:37.970923 23902 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:37.971187 23655 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:37.971279 23655 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/master-0-root
uuid: "5634397e1829441389bfe7e3400c92e2"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-07c2"
I20260812 06:17:37.971396 23655 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-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:37.980670 23655 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:37.981036 23655 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:37.985321 23655 rpc_server.cc:307] RPC server started. Bound to: 127.23.25.254:37729
I20260812 06:17:37.987224 23967 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.25.254:37729 every 8 connection(s)
I20260812 06:17:37.991339 23968 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:37.993228 23968 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2: Bootstrap starting.
I20260812 06:17:37.994007 23968 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:37.995065 23968 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2: No bootstrap required, opened a new log
I20260812 06:17:37.995548 23968 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5634397e1829441389bfe7e3400c92e2" member_type: VOTER }
I20260812 06:17:37.995664 23968 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:37.995715 23968 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5634397e1829441389bfe7e3400c92e2, State: Initialized, Role: FOLLOWER
I20260812 06:17:37.995872 23968 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [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: "5634397e1829441389bfe7e3400c92e2" member_type: VOTER }
I20260812 06:17:37.995967 23968 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:37.996016 23968 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:37.996073 23968 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:37.996820 23968 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5634397e1829441389bfe7e3400c92e2" member_type: VOTER }
I20260812 06:17:37.996974 23968 leader_election.cc:304] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [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: 5634397e1829441389bfe7e3400c92e2; no voters: 
I20260812 06:17:37.997179 23968 leader_election.cc:290] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:37.997354 23972 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:37.997583 23972 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 1 LEADER]: Becoming Leader. State: Replica: 5634397e1829441389bfe7e3400c92e2, State: Running, Role: LEADER
I20260812 06:17:37.997745 23968 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:37.997726 23972 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [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: "5634397e1829441389bfe7e3400c92e2" member_type: VOTER }
I20260812 06:17:37.998247 23973 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5634397e1829441389bfe7e3400c92e2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5634397e1829441389bfe7e3400c92e2" member_type: VOTER } }
I20260812 06:17:37.998273 23974 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5634397e1829441389bfe7e3400c92e2. Latest consensus state: current_term: 1 leader_uuid: "5634397e1829441389bfe7e3400c92e2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5634397e1829441389bfe7e3400c92e2" member_type: VOTER } }
I20260812 06:17:37.998420 23974 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:37.998404 23973 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:37.998986 23979 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:37.999804 23979 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:37.999986 23655 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:38.001682 23979 catalog_manager.cc:1383] Generated new cluster ID: 3da81279a972458bb949254434ea1678
I20260812 06:17:38.001751 23979 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:38.028143 23979 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:38.028757 23979 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:38.034170 23979 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2: Generated new TSK 0
I20260812 06:17:38.034353 23979 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:38.064752 23655 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:38.066931 23994 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.066919 23655 server_base.cc:1061] running on GCE node
W20260812 06:17:38.066917 23993 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.066917 23996 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.067474 23655 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:38.067520 23655 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.067538 23655 hybrid_clock.cc:648] HybridClock initialized: now 1786515458067538 us; error 0 us; skew 500 ppm
I20260812 06:17:38.068430 23655 webserver.cc:533] Webserver started at http://127.23.25.193:35467/ using document root <none> and password file <none>
I20260812 06:17:38.068593 23655 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:38.068640 23655 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:38.068692 23655 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:38.069047 23655 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/instance:
uuid: "a2de3076f43444f18c413fe449e370a1"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-07c2"
I20260812 06:17:38.070484 23655 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:38.071404 24001 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.071678 23655 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:38.071743 23655 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root
uuid: "a2de3076f43444f18c413fe449e370a1"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-07c2"
I20260812 06:17:38.071832 23655 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-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.086014 23655 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.086459 23655 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.086779 23655 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:38.087260 23655 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:38.087404 23655 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.087464 23655 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:38.087517 23655 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:38.092224 23655 rpc_server.cc:307] RPC server started. Bound to: 127.23.25.193:42803
I20260812 06:17:38.093437 24078 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.25.193:42803 every 8 connection(s)
I20260812 06:17:38.103019 24079 heartbeater.cc:344] Connected to a master server at 127.23.25.254:37729
I20260812 06:17:38.103112 24079 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:38.103443 24079 heartbeater.cc:507] Master 127.23.25.254:37729 requested a full tablet report, sending...
I20260812 06:17:38.104084 23923 ts_manager.cc:194] Registered new tserver with Master: a2de3076f43444f18c413fe449e370a1 (127.23.25.193:42803)
I20260812 06:17:38.104404 23655 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011153526s
I20260812 06:17:38.104943 23923 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51744
I20260812 06:17:38.111598 23923 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51758:
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.120180 24036 tablet_service.cc:1511] Processing CreateTablet for tablet 59e592e047f24e9681be230b45d7bdc5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2e36c370c9774c9fabb888bd9021680e]), partition=
I20260812 06:17:38.120467 24036 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 59e592e047f24e9681be230b45d7bdc5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:38.122427 24106 tablet_bootstrap.cc:492] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Bootstrap starting.
I20260812 06:17:38.123405 24106 tablet_bootstrap.cc:654] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.124423 24106 tablet_bootstrap.cc:492] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: No bootstrap required, opened a new log
I20260812 06:17:38.124532 24106 ts_tablet_manager.cc:1403] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:38.124941 24106 raft_consensus.cc:359] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2de3076f43444f18c413fe449e370a1" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 42803 } }
I20260812 06:17:38.125052 24106 raft_consensus.cc:385] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.125098 24106 raft_consensus.cc:740] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a2de3076f43444f18c413fe449e370a1, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.125265 24106 consensus_queue.cc:260] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [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: "a2de3076f43444f18c413fe449e370a1" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 42803 } }
I20260812 06:17:38.125377 24106 raft_consensus.cc:399] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.125423 24106 raft_consensus.cc:493] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.125478 24106 raft_consensus.cc:3060] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.126312 24106 raft_consensus.cc:515] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2de3076f43444f18c413fe449e370a1" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 42803 } }
I20260812 06:17:38.126466 24106 leader_election.cc:304] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [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: a2de3076f43444f18c413fe449e370a1; no voters: 
I20260812 06:17:38.126679 24106 leader_election.cc:290] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.126807 24108 raft_consensus.cc:2804] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.127024 24106 ts_tablet_manager.cc:1434] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:38.127034 24079 heartbeater.cc:499] Master 127.23.25.254:37729 was elected leader, sending a full tablet report...
I20260812 06:17:38.127045 24108 raft_consensus.cc:697] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 1 LEADER]: Becoming Leader. State: Replica: a2de3076f43444f18c413fe449e370a1, State: Running, Role: LEADER
I20260812 06:17:38.127278 24108 consensus_queue.cc:237] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [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: "a2de3076f43444f18c413fe449e370a1" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 42803 } }
I20260812 06:17:38.128568 23923 catalog_manager.cc:5719] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 reported cstate change: term changed from 0 to 1, leader changed from <none> to a2de3076f43444f18c413fe449e370a1 (127.23.25.193). New cstate: current_term: 1 leader_uuid: "a2de3076f43444f18c413fe449e370a1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2de3076f43444f18c413fe449e370a1" member_type: VOTER last_known_addr { host: "127.23.25.193" port: 42803 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:38.186647 23655 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.011s	sys 0.011s
I20260812 06:17:38.343973 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushMRSOp(59e592e047f24e9681be230b45d7bdc5): perf score=19.054940
I20260812 06:17:38.484501 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushMRSOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.140s	user 0.094s	sys 0.045s Metrics: {"bytes_written":12840810,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1034,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37238,"lbm_writes_lt_1ms":780,"mutex_wait_us":172,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":15744,"update_count":1565}
I20260812 06:17:38.485132 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5): 16821648 bytes on disk
I20260812 06:17:38.485531 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.485989 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling LogGCOp(59e592e047f24e9681be230b45d7bdc5): free 20743880 bytes of WAL
I20260812 06:17:38.486250 24007 log_reader.cc:385] T 59e592e047f24e9681be230b45d7bdc5: removed 2 log segments from log reader
I20260812 06:17:38.486315 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000001 (ops 1-6)
I20260812 06:17:38.486356 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000002 (ops 7-11)
I20260812 06:17:38.492272 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: LogGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:38.493294 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:38.508810 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3569335,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:17:38.509228 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:38.518512 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3503,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.518931 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:38.687373 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.168s	user 0.123s	sys 0.041s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405545,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":845,"lbm_read_time_us":13045,"lbm_reads_lt_1ms":559,"lbm_write_time_us":26534,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":333,"threads_started":5,"update_count":2450}
I20260812 06:17:38.688060 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:38.731567 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.043s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19243,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.732054 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:38.892674 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.160s	user 0.080s	sys 0.077s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713151,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":582,"lbm_read_time_us":11216,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25235,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:38.893436 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:38.941529 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22225,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.942018 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:38.953534 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3941,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.954211 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:39.127506 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.173s	user 0.114s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":257,"lbm_read_time_us":9812,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26887,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33280,"update_count":2500}
I20260812 06:17:39.128219 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:39.181114 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.053s	user 0.045s	sys 0.001s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21232,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.181612 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:39.192900 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.011s	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:39.193614 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:39.349385 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.156s	user 0.113s	sys 0.038s 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":934,"lbm_read_time_us":11717,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28904,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:17:39.350092 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:39.397691 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.047s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":20944,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.398202 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:39.409693 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.410435 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:39.552425 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.142s	user 0.125s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815678,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":10881,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27869,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:39.553088 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=11.118625
I20260812 06:17:39.588053 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.035s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15303,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:39.588590 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:39.606460 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6074,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.609519 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushMRSOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:39.645524 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushMRSOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.036s	user 0.023s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1547,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:39.646139 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling LogGCOp(59e592e047f24e9681be230b45d7bdc5): free 112692387 bytes of WAL
I20260812 06:17:39.646404 24007 log_reader.cc:385] T 59e592e047f24e9681be230b45d7bdc5: removed 11 log segments from log reader
I20260812 06:17:39.646474 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000003 (ops 12-16)
I20260812 06:17:39.646549 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000004 (ops 17-21)
I20260812 06:17:39.646611 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000005 (ops 22-26)
I20260812 06:17:39.646682 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000006 (ops 27-31)
I20260812 06:17:39.646744 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000007 (ops 32-36)
I20260812 06:17:39.646813 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000008 (ops 37-41)
I20260812 06:17:39.646854 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000009 (ops 42-46)
I20260812 06:17:39.646900 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000010 (ops 47-51)
I20260812 06:17:39.646942 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000011 (ops 52-56)
I20260812 06:17:39.646986 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000012 (ops 57-61)
I20260812 06:17:39.647027 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000013 (ops 62-66)
I20260812 06:17:39.669497 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: LogGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:39.669984 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5): 447 bytes on disk
I20260812 06:17:39.670408 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:39.673305 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=6.157687
I20260812 06:17:39.700075 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.027s	user 0.017s	sys 0.008s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10865,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:39.700498 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling LogGCOp(59e592e047f24e9681be230b45d7bdc5): free 11564875 bytes of WAL
I20260812 06:17:39.700707 24007 log_reader.cc:385] T 59e592e047f24e9681be230b45d7bdc5: removed 1 log segments from log reader
I20260812 06:17:39.700752 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000014 (ops 67-70)
I20260812 06:17:39.703006 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: LogGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:39.703357 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:39.866799 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.163s	user 0.125s	sys 0.037s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918207,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":754,"lbm_read_time_us":11522,"lbm_reads_lt_1ms":665,"lbm_write_time_us":32413,"lbm_writes_lt_1ms":643,"mutex_wait_us":89,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28288,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:17:39.867522 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=15.087375
I20260812 06:17:39.925910 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.058s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22678,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:39.926357 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:39.936848 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4037,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.937283 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:39.946913 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.947425 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:40.111330 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.164s	user 0.123s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":386,"lbm_read_time_us":11168,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34356,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:40.111907 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:40.165251 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.053s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22617,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.165776 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:40.181277 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5384,"lbm_writes_lt_1ms":103,"mutex_wait_us":3,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.181831 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:40.330091 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.148s	user 0.104s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":937,"lbm_read_time_us":8825,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28082,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:40.330860 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:40.404877 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.074s	user 0.022s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27557,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.405435 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:40.415870 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.416474 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:40.589962 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.173s	user 0.100s	sys 0.071s 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":194,"lbm_read_time_us":11555,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30383,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:17:40.590533 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:40.644596 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.054s	user 0.021s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22819,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.645160 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:40.657950 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.658443 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:40.831178 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.173s	user 0.136s	sys 0.036s 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":560,"lbm_read_time_us":13011,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29506,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:17:40.831837 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=15.087375
I20260812 06:17:40.890952 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.059s	user 0.045s	sys 0.011s Metrics: {"bytes_written":16820138,"delete_count":0,"lbm_write_time_us":22899,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:40.891549 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:40.915215 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.023s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:40.915738 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:40.925957 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.926515 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushMRSOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:40.956728 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushMRSOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.030s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1303,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1432,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:40.957432 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling LogGCOp(59e592e047f24e9681be230b45d7bdc5): free 112692315 bytes of WAL
I20260812 06:17:40.957669 24007 log_reader.cc:385] T 59e592e047f24e9681be230b45d7bdc5: removed 11 log segments from log reader
I20260812 06:17:40.957712 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000015 (ops 71-75)
I20260812 06:17:40.957742 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000016 (ops 76-80)
I20260812 06:17:40.957805 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000017 (ops 81-85)
I20260812 06:17:40.957850 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000018 (ops 86-90)
I20260812 06:17:40.957912 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000019 (ops 91-95)
I20260812 06:17:40.957952 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000020 (ops 96-100)
I20260812 06:17:40.958011 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000021 (ops 101-105)
I20260812 06:17:40.958040 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000022 (ops 106-110)
I20260812 06:17:40.958077 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000023 (ops 111-115)
I20260812 06:17:40.958101 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000024 (ops 116-120)
I20260812 06:17:40.958166 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000025 (ops 121-125)
I20260812 06:17:40.982510 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: LogGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:40.983068 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5): 447 bytes on disk
I20260812 06:17:40.983551 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:40.984118 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:41.005759 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.021s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.006282 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:41.016788 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.017402 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:41.259711 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.242s	user 0.148s	sys 0.091s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123258,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":546,"lbm_read_time_us":16725,"lbm_reads_lt_1ms":875,"lbm_write_time_us":44154,"lbm_writes_lt_1ms":843,"mutex_wait_us":77,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":30336,"thread_start_us":86,"threads_started":1,"update_count":4000}
I20260812 06:17:41.260423 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=18.063937
I20260812 06:17:41.332373 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.072s	user 0.029s	sys 0.037s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31720,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:41.333040 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=3.181125
I20260812 06:17:41.356329 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.023s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7099,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:41.356777 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:41.366358 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3552,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:41.366819 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:41.562142 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.195s	user 0.155s	sys 0.040s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020618,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":991,"lbm_read_time_us":14366,"lbm_reads_lt_1ms":773,"lbm_write_time_us":40456,"lbm_writes_lt_1ms":743,"mutex_wait_us":642,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3500}
I20260812 06:17:41.562831 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:41.607578 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.045s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20024,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.608139 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:41.626777 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5610,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.627689 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:41.780464 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.153s	user 0.116s	sys 0.036s 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":647,"lbm_read_time_us":8573,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27676,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:41.781095 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:41.824062 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.043s	user 0.014s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19397,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.824612 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:41.837347 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.837813 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:42.025504 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.187s	user 0.123s	sys 0.060s 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":137,"lbm_read_time_us":12190,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32549,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2500}
I20260812 06:17:42.029659 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:42.090655 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.061s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24476,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.091189 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:42.107453 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.108719 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:42.269953 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.161s	user 0.101s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":766,"lbm_read_time_us":11660,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26425,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:17:42.270533 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=14.095187
I20260812 06:17:42.327781 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.057s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19810,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.328330 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:42.338711 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.339128 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushMRSOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:42.382195 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushMRSOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.043s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":167,"dirs.run_wall_time_us":1477,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1586,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:42.382900 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling LogGCOp(59e592e047f24e9681be230b45d7bdc5): free 112239591 bytes of WAL
I20260812 06:17:42.383119 24007 log_reader.cc:385] T 59e592e047f24e9681be230b45d7bdc5: removed 11 log segments from log reader
I20260812 06:17:42.383180 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000026 (ops 126-130)
I20260812 06:17:42.383235 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000027 (ops 131-134)
I20260812 06:17:42.383293 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000028 (ops 135-139)
I20260812 06:17:42.383360 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000029 (ops 140-144)
I20260812 06:17:42.383401 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000030 (ops 145-149)
I20260812 06:17:42.383440 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000031 (ops 150-154)
I20260812 06:17:42.383481 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000032 (ops 155-159)
I20260812 06:17:42.383525 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000033 (ops 160-164)
I20260812 06:17:42.383565 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000034 (ops 165-169)
I20260812 06:17:42.383612 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000035 (ops 170-174)
I20260812 06:17:42.383652 24007 log.cc:1079] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: Deleting log segment in path: /tmp/dist-test-taskCJaAbq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452398925-23655-0/minicluster-data/ts-0-root/wals/59e592e047f24e9681be230b45d7bdc5/wal-000000036 (ops 175-179)
I20260812 06:17:42.407430 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: LogGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.024s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:42.407943 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=3.181125
I20260812 06:17:42.424575 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.016s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4572,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:42.425053 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:42.434814 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3748,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.435386 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:42.650000 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.214s	user 0.134s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":483,"lbm_read_time_us":15201,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37769,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:17:42.650781 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=18.063937
I20260812 06:17:42.717181 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.066s	user 0.033s	sys 0.031s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28524,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:42.717682 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:42.741710 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.024s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.742200 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5): perf score=2.188937
I20260812 06:17:42.752481 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: FlushDeltaMemStoresOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.752892 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5): 463 bytes on disk
I20260812 06:17:42.753271 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: UndoDeltaBlockGCOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.753755 24080 maintenance_manager.cc:419] P a2de3076f43444f18c413fe449e370a1: Scheduling MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5): perf score=1.000000
I20260812 06:17:42.790499 23655 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.604s	user 1.738s	sys 0.127s
I20260812 06:17:42.858040 23655 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.000s	sys 0.001s
I20260812 06:17:42.858564 23655 tablet_server.cc:179] TabletServer@127.23.25.193:0 shutting down...
I20260812 06:17:42.921432 24007 maintenance_manager.cc:643] P a2de3076f43444f18c413fe449e370a1: MajorDeltaCompactionOp(59e592e047f24e9681be230b45d7bdc5) complete. Timing: real 0.168s	user 0.133s	sys 0.034s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020629,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":259,"lbm_read_time_us":14734,"lbm_reads_lt_1ms":769,"lbm_write_time_us":34714,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":3500}
I20260812 06:17:42.922290 23655 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:42.922531 23655 tablet_replica.cc:333] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1: stopping tablet replica
I20260812 06:17:42.922703 23655 raft_consensus.cc:2243] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:42.922883 23655 raft_consensus.cc:2272] T 59e592e047f24e9681be230b45d7bdc5 P a2de3076f43444f18c413fe449e370a1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:42.928004 23655 tablet_server.cc:196] TabletServer@127.23.25.193:0 shutdown complete.
I20260812 06:17:42.981351 23655 master.cc:562] Master@127.23.25.254:37729 shutting down...
I20260812 06:17:42.985159 23655 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:42.985332 23655 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:42.985383 23655 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5634397e1829441389bfe7e3400c92e2: stopping tablet replica
I20260812 06:17:42.997686 23655 master.cc:584] Master@127.23.25.254:37729 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5135 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10679 ms total)

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