[==========] 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:20:16.735988  9873 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.164.126:44771
I20260812 06:20:16.737365  9873 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:20:16.738148  9873 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:16.745815  9879 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:20:16.746040  9873 server_base.cc:1061] running on GCE node
W20260812 06:20:16.746126  9881 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:20:16.745894  9878 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:20:16.746981  9873 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:16.747176  9873 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:20:16.747247  9873 hybrid_clock.cc:648] HybridClock initialized: now 1786515616747243 us; error 0 us; skew 500 ppm
I20260812 06:20:16.749577  9873 webserver.cc:533] Webserver started at http://127.9.164.126:46039/ using document root <none> and password file <none>
I20260812 06:20:16.750285  9873 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:16.750393  9873 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:16.750705  9873 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:16.752681  9873 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/master-0-root/instance:
uuid: "457c84cd398742a4b79b5b20e809604e"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-ss4n"
I20260812 06:20:16.757205  9873 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.006s	sys 0.000s
I20260812 06:20:16.760125  9886 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:20:16.761778  9873 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:16.761982  9873 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/master-0-root
uuid: "457c84cd398742a4b79b5b20e809604e"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-ss4n"
I20260812 06:20:16.762149  9873 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-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:20:16.776111  9873 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:16.776942  9873 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:20:16.777171  9873 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:16.786643  9873 rpc_server.cc:307] RPC server started. Bound to: 127.9.164.126:44771
I20260812 06:20:16.786715  9951 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.164.126:44771 every 8 connection(s)
I20260812 06:20:16.789393  9952 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:20:16.795920  9952 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e: Bootstrap starting.
I20260812 06:20:16.798859  9952 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.800006  9952 log.cc:826] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:16.802537  9952 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e: No bootstrap required, opened a new log
I20260812 06:20:16.806243  9952 raft_consensus.cc:359] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "457c84cd398742a4b79b5b20e809604e" member_type: VOTER }
I20260812 06:20:16.806499  9952 raft_consensus.cc:385] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.806552  9952 raft_consensus.cc:740] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 457c84cd398742a4b79b5b20e809604e, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.807363  9952 consensus_queue.cc:260] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [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: "457c84cd398742a4b79b5b20e809604e" member_type: VOTER }
I20260812 06:20:16.807554  9952 raft_consensus.cc:399] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.807708  9952 raft_consensus.cc:493] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.807899  9952 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.808938  9952 raft_consensus.cc:515] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "457c84cd398742a4b79b5b20e809604e" member_type: VOTER }
I20260812 06:20:16.809592  9952 leader_election.cc:304] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [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: 457c84cd398742a4b79b5b20e809604e; no voters: 
I20260812 06:20:16.810045  9952 leader_election.cc:290] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.810292  9955 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.810652  9955 raft_consensus.cc:697] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 1 LEADER]: Becoming Leader. State: Replica: 457c84cd398742a4b79b5b20e809604e, State: Running, Role: LEADER
I20260812 06:20:16.811141  9955 consensus_queue.cc:237] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [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: "457c84cd398742a4b79b5b20e809604e" member_type: VOTER }
I20260812 06:20:16.811452  9952 sys_catalog.cc:565] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:16.813604  9956 sys_catalog.cc:455] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "457c84cd398742a4b79b5b20e809604e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "457c84cd398742a4b79b5b20e809604e" member_type: VOTER } }
I20260812 06:20:16.813792  9956 sys_catalog.cc:458] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:16.813727  9957 sys_catalog.cc:455] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 457c84cd398742a4b79b5b20e809604e. Latest consensus state: current_term: 1 leader_uuid: "457c84cd398742a4b79b5b20e809604e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "457c84cd398742a4b79b5b20e809604e" member_type: VOTER } }
I20260812 06:20:16.813855  9957 sys_catalog.cc:458] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:16.814169  9971 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:16.814425  9873 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:16.817039  9971 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:16.822563  9971 catalog_manager.cc:1383] Generated new cluster ID: 929ba9fb7632429dab214020367ac374
I20260812 06:20:16.822679  9971 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:16.835850  9971 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:16.836902  9971 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:16.844584  9971 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e: Generated new TSK 0
I20260812 06:20:16.845468  9971 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:16.847529  9873 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:16.851042  9982 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:20:16.851204  9980 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:20:16.851274  9873 server_base.cc:1061] running on GCE node
W20260812 06:20:16.851037  9979 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:20:16.851706  9873 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:16.851806  9873 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:20:16.851838  9873 hybrid_clock.cc:648] HybridClock initialized: now 1786515616851838 us; error 0 us; skew 500 ppm
I20260812 06:20:16.852953  9873 webserver.cc:533] Webserver started at http://127.9.164.65:42609/ using document root <none> and password file <none>
I20260812 06:20:16.853178  9873 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:16.853260  9873 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:16.853375  9873 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:16.853858  9873 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/instance:
uuid: "eeb0a968918949ba815826a8518794ea"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-ss4n"
I20260812 06:20:16.855496  9873 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:20:16.856607  9988 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:20:16.856887  9873 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:16.856957  9873 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root
uuid: "eeb0a968918949ba815826a8518794ea"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-ss4n"
I20260812 06:20:16.857059  9873 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-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:20:16.874701  9873 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:16.875958  9873 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:16.876672  9873 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:16.877852  9873 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:16.877919  9873 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.878015  9873 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:16.878067  9873 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.886965  9873 rpc_server.cc:307] RPC server started. Bound to: 127.9.164.65:43863
I20260812 06:20:16.887012 10067 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.164.65:43863 every 8 connection(s)
I20260812 06:20:16.912374 10068 heartbeater.cc:344] Connected to a master server at 127.9.164.126:44771
I20260812 06:20:16.912719 10068 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:16.913331 10068 heartbeater.cc:507] Master 127.9.164.126:44771 requested a full tablet report, sending...
I20260812 06:20:16.915400  9900 ts_manager.cc:194] Registered new tserver with Master: eeb0a968918949ba815826a8518794ea (127.9.164.65:43863)
I20260812 06:20:16.915938  9873 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.028145782s
I20260812 06:20:16.917192  9900 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60656
I20260812 06:20:16.927843  9900 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60668:
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:20:16.944199 10025 tablet_service.cc:1511] Processing CreateTablet for tablet 3f148a3ad56f4436a77ea380839a7670 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8efcd1a673494e3f956001180ecfec23]), partition=
I20260812 06:20:16.944729 10025 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3f148a3ad56f4436a77ea380839a7670. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:16.947310 10080 tablet_bootstrap.cc:492] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Bootstrap starting.
I20260812 06:20:16.948374 10080 tablet_bootstrap.cc:654] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.949887 10080 tablet_bootstrap.cc:492] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: No bootstrap required, opened a new log
I20260812 06:20:16.950022 10080 ts_tablet_manager.cc:1403] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:16.950519 10080 raft_consensus.cc:359] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb0a968918949ba815826a8518794ea" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 43863 } }
I20260812 06:20:16.950665 10080 raft_consensus.cc:385] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.950716 10080 raft_consensus.cc:740] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eeb0a968918949ba815826a8518794ea, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.950898 10080 consensus_queue.cc:260] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [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: "eeb0a968918949ba815826a8518794ea" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 43863 } }
I20260812 06:20:16.951025 10080 raft_consensus.cc:399] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.951083 10080 raft_consensus.cc:493] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.951148 10080 raft_consensus.cc:3060] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.952521 10080 raft_consensus.cc:515] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb0a968918949ba815826a8518794ea" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 43863 } }
I20260812 06:20:16.952697 10080 leader_election.cc:304] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [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: eeb0a968918949ba815826a8518794ea; no voters: 
I20260812 06:20:16.952958 10080 leader_election.cc:290] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.953135 10082 raft_consensus.cc:2804] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.953428 10082 raft_consensus.cc:697] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 1 LEADER]: Becoming Leader. State: Replica: eeb0a968918949ba815826a8518794ea, State: Running, Role: LEADER
I20260812 06:20:16.953444 10080 ts_tablet_manager.cc:1434] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:20:16.953670 10068 heartbeater.cc:499] Master 127.9.164.126:44771 was elected leader, sending a full tablet report...
I20260812 06:20:16.953883 10082 consensus_queue.cc:237] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [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: "eeb0a968918949ba815826a8518794ea" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 43863 } }
I20260812 06:20:16.957197  9900 catalog_manager.cc:5719] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea reported cstate change: term changed from 0 to 1, leader changed from <none> to eeb0a968918949ba815826a8518794ea (127.9.164.65). New cstate: current_term: 1 leader_uuid: "eeb0a968918949ba815826a8518794ea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb0a968918949ba815826a8518794ea" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 43863 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:17.038926  9873 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.074s	user 0.023s	sys 0.016s
I20260812 06:20:17.138458 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushMRSOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.125253
I20260812 06:20:17.276957  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushMRSOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.138s	user 0.126s	sys 0.008s Metrics: {"bytes_written":8697371,"cfile_init":1,"compiler_manager_pool.queue_time_us":267,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1224,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":29530,"lbm_writes_lt_1ms":469,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"spinlock_wait_cycles":289536,"thread_start_us":119,"threads_started":1,"update_count":1060}
I20260812 06:20:17.278247 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling LogGCOp(3f148a3ad56f4436a77ea380839a7670): free 8725963 bytes of WAL
I20260812 06:20:17.278600  9994 log_reader.cc:385] T 3f148a3ad56f4436a77ea380839a7670: removed 1 log segments from log reader
I20260812 06:20:17.278682  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000001 (ops 1-6)
I20260812 06:20:17.280774  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: LogGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:17.281179 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:17.294649  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":4692,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:20:17.295198 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:17.429630  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.134s	user 0.117s	sys 0.016s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487924,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1257,"lbm_read_time_us":9486,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21902,"lbm_writes_lt_1ms":343,"mutex_wait_us":31,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":538,"threads_started":5,"update_count":1500}
I20260812 06:20:17.430348 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670): 8206537 bytes on disk
I20260812 06:20:17.430914  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.431479 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=8.142062
I20260812 06:20:17.476483  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.045s	user 0.019s	sys 0.022s Metrics: {"bytes_written":10379356,"delete_count":0,"lbm_write_time_us":21143,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":255,"mutex_wait_us":1219,"reinsert_count":0,"update_count":1265}
I20260812 06:20:17.477003 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:17.488667  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.011s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1928327,"delete_count":0,"lbm_write_time_us":2099,"lbm_writes_lt_1ms":50,"reinsert_count":0,"update_count":235}
I20260812 06:20:17.489231 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:17.614097  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.125s	user 0.077s	sys 0.047s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487882,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":8248,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21468,"lbm_writes_lt_1ms":343,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":1500}
I20260812 06:20:17.614708 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:17.654031  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.039s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16719,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.654703 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:17.672052  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.672591 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:17.813580  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.141s	user 0.104s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1146,"lbm_read_time_us":11858,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28564,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:20:17.814368 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:17.864964  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.050s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17174,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.865605 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:17.878057  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.878762 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:18.013785  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.135s	user 0.090s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1000,"lbm_read_time_us":9212,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28703,"lbm_writes_lt_1ms":443,"mutex_wait_us":344,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:18.014369 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:18.070675  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.056s	user 0.022s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16769,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.071228 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:18.082813  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.083381 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:18.257334  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.174s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":13193,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29875,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:20:18.258092 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:18.312790  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.055s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17822,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":1500}
I20260812 06:20:18.313712 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:18.334769  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.021s	user 0.015s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.335374 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:18.480886  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.145s	user 0.115s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1307,"lbm_read_time_us":12591,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27823,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:20:18.481464 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:18.520855  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.039s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16942,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.521445 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:18.534641  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.535552 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:18.680559  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.145s	user 0.117s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4760,"lbm_read_time_us":11389,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26617,"lbm_writes_lt_1ms":443,"mutex_wait_us":3418,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:20:18.681557 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:18.732510  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.051s	user 0.022s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16783,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.733196 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:18.745841  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.746428 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushMRSOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:18.789069  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushMRSOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.042s	user 0.033s	sys 0.004s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":115,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1532,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1660,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:18.790086 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling LogGCOp(3f148a3ad56f4436a77ea380839a7670): free 124257246 bytes of WAL
I20260812 06:20:18.790352  9994 log_reader.cc:385] T 3f148a3ad56f4436a77ea380839a7670: removed 12 log segments from log reader
I20260812 06:20:18.790400  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000002 (ops 7-11)
I20260812 06:20:18.790431  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000003 (ops 12-16)
I20260812 06:20:18.790493  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000004 (ops 17-20)
I20260812 06:20:18.790540  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000005 (ops 21-25)
I20260812 06:20:18.790586  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000006 (ops 26-30)
I20260812 06:20:18.790628  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000007 (ops 31-35)
I20260812 06:20:18.790697  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000008 (ops 36-40)
I20260812 06:20:18.790743  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000009 (ops 41-45)
I20260812 06:20:18.790791  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000010 (ops 46-50)
I20260812 06:20:18.790835  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000011 (ops 51-55)
I20260812 06:20:18.790876  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000012 (ops 56-60)
I20260812 06:20:18.790917  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000013 (ops 61-65)
I20260812 06:20:18.824401  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: LogGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:18.825048 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=3.181125
I20260812 06:20:18.843848  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.018s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6364,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:18.844408 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:18.854964  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.855548 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:19.079284  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.223s	user 0.133s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795396,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1113,"lbm_read_time_us":14979,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36452,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:20:19.080116 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=14.095187
I20260812 06:20:19.133411  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.053s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23351,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.134125 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:19.294519  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.160s	user 0.108s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590226,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1406,"lbm_read_time_us":10656,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28085,"lbm_writes_lt_1ms":443,"mutex_wait_us":405,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:20:19.295316 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670): 473 bytes on disk
I20260812 06:20:19.295825  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.296373 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:19.339394  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.043s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19055,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.340023 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:19.361968  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.362682 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:19.501019  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.138s	user 0.100s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":11188,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27407,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:19.501849 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:19.543943  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.042s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17341,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.544617 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:19.561344  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.017s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.562165 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:19.710978  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.148s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":405,"lbm_read_time_us":10781,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29487,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21504,"update_count":2000}
I20260812 06:20:19.711665 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:19.762523  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.051s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19702,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.763211 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:19.779327  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.780176 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:19.927682  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.147s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":11185,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29232,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":2000}
I20260812 06:20:19.928326 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:19.983327  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.055s	user 0.030s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19559,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.984028 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:19.995139  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.995630 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:20.160498  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.165s	user 0.116s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1165,"lbm_read_time_us":12639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26661,"lbm_writes_lt_1ms":443,"mutex_wait_us":368,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:20:20.161278 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:20.213021  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.051s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15454,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.213784 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:20.225829  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.226603 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:20.363377  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.137s	user 0.106s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":10888,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27110,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":89856,"update_count":2000}
I20260812 06:20:20.364187 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:20.403844  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.039s	user 0.014s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17103,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.404434 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushMRSOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:20.458364  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushMRSOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.054s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1629,"drs_written":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1855,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":2432}
I20260812 06:20:20.459200 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling LogGCOp(3f148a3ad56f4436a77ea380839a7670): free 124257248 bytes of WAL
I20260812 06:20:20.459520  9994 log_reader.cc:385] T 3f148a3ad56f4436a77ea380839a7670: removed 12 log segments from log reader
I20260812 06:20:20.459597  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000014 (ops 66-70)
I20260812 06:20:20.459642  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000015 (ops 71-74)
I20260812 06:20:20.459676  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000016 (ops 75-79)
I20260812 06:20:20.459713  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000017 (ops 80-84)
I20260812 06:20:20.459745  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000018 (ops 85-89)
I20260812 06:20:20.459780  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000019 (ops 90-94)
I20260812 06:20:20.459806  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000020 (ops 95-99)
I20260812 06:20:20.459831  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000021 (ops 100-104)
I20260812 06:20:20.459863  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000022 (ops 105-109)
I20260812 06:20:20.459892  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000023 (ops 110-114)
I20260812 06:20:20.459925  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000024 (ops 115-119)
I20260812 06:20:20.459961  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000025 (ops 120-124)
I20260812 06:20:20.495503  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: LogGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.036s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:20:20.495998 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670): 473 bytes on disk
I20260812 06:20:20.496512  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:20:20.497139 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=6.157687
I20260812 06:20:20.522898  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.026s	user 0.016s	sys 0.008s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":10983,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:20.523429 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:20.537967  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.538626 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:20.722167  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.183s	user 0.139s	sys 0.039s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795290,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":150,"lbm_read_time_us":13258,"lbm_reads_lt_1ms":665,"lbm_write_time_us":36375,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:20:20.723007 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=14.095187
I20260812 06:20:20.787510  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.064s	user 0.030s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28146,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.788082 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:20.819990  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.032s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6490,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.820606 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:20.832849  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.833556 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:21.033571  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.200s	user 0.140s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795289,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":465,"lbm_read_time_us":14368,"lbm_reads_lt_1ms":673,"lbm_write_time_us":43865,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":32256,"update_count":3000}
I20260812 06:20:21.034188 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=11.118625
I20260812 06:20:21.080768  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.046s	user 0.026s	sys 0.017s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":20386,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.081930 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:21.101605  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.019s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4904,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.102206 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:21.117970  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.118546 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:21.299510  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.181s	user 0.107s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692868,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":884,"lbm_read_time_us":12934,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34797,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:20:21.300292 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=11.118625
I20260812 06:20:21.345193  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.044s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19314,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.346165 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:21.367712  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.021s	user 0.016s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6700,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.368357 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:21.504371  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.136s	user 0.100s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590340,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":386,"lbm_read_time_us":8549,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28336,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:21.505343 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:21.556295  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.051s	user 0.030s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21730,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.556924 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:21.568312  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.568979 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:21.704949  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.136s	user 0.111s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1419,"lbm_read_time_us":10402,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25318,"lbm_writes_lt_1ms":443,"mutex_wait_us":533,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":137984,"update_count":2000}
I20260812 06:20:21.705886 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:21.757421  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.051s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16661,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.758219 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:21.771318  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.771936 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:21.962484  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.190s	user 0.146s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1306,"lbm_read_time_us":15045,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30565,"lbm_writes_lt_1ms":443,"mutex_wait_us":366,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:20:21.963380 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=10.126437
I20260812 06:20:22.002637  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.039s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16995,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.003239 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:22.015673  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.016224 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushMRSOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:22.051268  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushMRSOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":2263,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2376,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:22.052254 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling LogGCOp(3f148a3ad56f4436a77ea380839a7670): free 124710544 bytes of WAL
I20260812 06:20:22.052605  9994 log_reader.cc:385] T 3f148a3ad56f4436a77ea380839a7670: removed 12 log segments from log reader
I20260812 06:20:22.052672  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000026 (ops 125-129)
I20260812 06:20:22.052758  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000027 (ops 130-134)
I20260812 06:20:22.052805  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000028 (ops 135-139)
I20260812 06:20:22.052845  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000029 (ops 140-144)
I20260812 06:20:22.052878  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000030 (ops 145-149)
I20260812 06:20:22.052914  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000031 (ops 150-154)
I20260812 06:20:22.052953  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000032 (ops 155-159)
I20260812 06:20:22.052992  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000033 (ops 160-164)
I20260812 06:20:22.053033  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000034 (ops 165-169)
I20260812 06:20:22.053073  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000035 (ops 170-174)
I20260812 06:20:22.053112  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000036 (ops 175-179)
I20260812 06:20:22.053157  9994 log.cc:1079] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/3f148a3ad56f4436a77ea380839a7670/wal-000000037 (ops 180-184)
I20260812 06:20:22.084470  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: LogGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.032s	user 0.001s	sys 0.028s Metrics: {}
I20260812 06:20:22.085139 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670): 462 bytes on disk
I20260812 06:20:22.086123  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: UndoDeltaBlockGCOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.001s	user 0.000s	sys 0.001s Metrics: {"cfile_init":1,"lbm_read_time_us":141,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.087242 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=3.181125
I20260812 06:20:22.103267  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.016s	user 0.011s	sys 0.002s Metrics: {"bytes_written":4800074,"delete_count":0,"lbm_write_time_us":6176,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:20:22.103886 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:22.125893  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.022s	user 0.010s	sys 0.011s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":4603,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:20:22.126616 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:22.350756  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.224s	user 0.140s	sys 0.081s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795395,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":332,"lbm_read_time_us":18040,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37811,"lbm_writes_lt_1ms":643,"mutex_wait_us":92,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":145,"threads_started":1,"update_count":3000}
I20260812 06:20:22.351977 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=14.095187
I20260812 06:20:22.423081  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.071s	user 0.030s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22784,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.423918 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=2.188937
I20260812 06:20:22.440930  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.441730 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670): perf score=1.000000
I20260812 06:20:22.554507  9873 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.515s	user 2.025s	sys 0.174s
I20260812 06:20:22.616645  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: MajorDeltaCompactionOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.175s	user 0.093s	sys 0.081s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":998,"lbm_read_time_us":14551,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30493,"lbm_writes_lt_1ms":543,"mutex_wait_us":209,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2500}
I20260812 06:20:22.617535 10069 maintenance_manager.cc:419] P eeb0a968918949ba815826a8518794ea: Scheduling FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670): perf score=6.157687
I20260812 06:20:22.633533  9873 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.006s	sys 0.000s
I20260812 06:20:22.634424  9873 tablet_server.cc:179] TabletServer@127.9.164.65:0 shutting down...
I20260812 06:20:22.647475  9994 maintenance_manager.cc:643] P eeb0a968918949ba815826a8518794ea: FlushDeltaMemStoresOp(3f148a3ad56f4436a77ea380839a7670) complete. Timing: real 0.030s	user 0.022s	sys 0.005s Metrics: {"bytes_written":8205081,"delete_count":0,"lbm_write_time_us":13138,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:22.648177  9873 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:22.648630  9873 tablet_replica.cc:333] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea: stopping tablet replica
I20260812 06:20:22.648873  9873 raft_consensus.cc:2243] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.649087  9873 raft_consensus.cc:2272] T 3f148a3ad56f4436a77ea380839a7670 P eeb0a968918949ba815826a8518794ea [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.665051  9873 tablet_server.cc:196] TabletServer@127.9.164.65:0 shutdown complete.
I20260812 06:20:22.670684  9873 master.cc:562] Master@127.9.164.126:44771 shutting down...
I20260812 06:20:22.674393  9873 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.674597  9873 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.674702  9873 tablet_replica.cc:333] T 00000000000000000000000000000000 P 457c84cd398742a4b79b5b20e809604e: stopping tablet replica
I20260812 06:20:22.687389  9873 master.cc:584] Master@127.9.164.126:44771 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6049 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:22.798197  9873 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.164.126:38461
I20260812 06:20:22.798676  9873 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:22.801205  9873 server_base.cc:1061] running on GCE node
W20260812 06:20:22.801450 10105 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:20:22.801581 10107 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:20:22.801577 10104 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:20:22.802014  9873 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.802066  9873 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:20:22.802122  9873 hybrid_clock.cc:648] HybridClock initialized: now 1786515622802121 us; error 0 us; skew 500 ppm
I20260812 06:20:22.803169  9873 webserver.cc:533] Webserver started at http://127.9.164.126:37565/ using document root <none> and password file <none>
I20260812 06:20:22.803383  9873 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.803472  9873 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.803570  9873 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.804049  9873 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/master-0-root/instance:
uuid: "a6a8211e4e5f43ebb38eb5073b787e21"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-ss4n"
I20260812 06:20:22.805896  9873 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:22.807053 10113 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:20:22.807641  9873 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:22.807762  9873 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/master-0-root
uuid: "a6a8211e4e5f43ebb38eb5073b787e21"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-ss4n"
I20260812 06:20:22.807868  9873 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-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:20:22.830006  9873 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.830482  9873 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.835461  9873 rpc_server.cc:307] RPC server started. Bound to: 127.9.164.126:38461
I20260812 06:20:22.838439 10173 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.164.126:38461 every 8 connection(s)
I20260812 06:20:22.839043 10174 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:20:22.841022 10174 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21: Bootstrap starting.
I20260812 06:20:22.841943 10174 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.843461 10174 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21: No bootstrap required, opened a new log
I20260812 06:20:22.844089 10174 raft_consensus.cc:359] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a6a8211e4e5f43ebb38eb5073b787e21" member_type: VOTER }
I20260812 06:20:22.844199 10174 raft_consensus.cc:385] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.844225 10174 raft_consensus.cc:740] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a6a8211e4e5f43ebb38eb5073b787e21, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.844408 10174 consensus_queue.cc:260] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [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: "a6a8211e4e5f43ebb38eb5073b787e21" member_type: VOTER }
I20260812 06:20:22.844496 10174 raft_consensus.cc:399] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.844568 10174 raft_consensus.cc:493] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.844638 10174 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.845633 10174 raft_consensus.cc:515] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a6a8211e4e5f43ebb38eb5073b787e21" member_type: VOTER }
I20260812 06:20:22.845815 10174 leader_election.cc:304] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [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: a6a8211e4e5f43ebb38eb5073b787e21; no voters: 
I20260812 06:20:22.846110 10174 leader_election.cc:290] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.846371 10177 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.846719 10177 raft_consensus.cc:697] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 1 LEADER]: Becoming Leader. State: Replica: a6a8211e4e5f43ebb38eb5073b787e21, State: Running, Role: LEADER
I20260812 06:20:22.846871 10174 sys_catalog.cc:565] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:22.846937 10177 consensus_queue.cc:237] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [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: "a6a8211e4e5f43ebb38eb5073b787e21" member_type: VOTER }
I20260812 06:20:22.847477 10179 sys_catalog.cc:455] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a6a8211e4e5f43ebb38eb5073b787e21. Latest consensus state: current_term: 1 leader_uuid: "a6a8211e4e5f43ebb38eb5073b787e21" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a6a8211e4e5f43ebb38eb5073b787e21" member_type: VOTER } }
I20260812 06:20:22.847460 10178 sys_catalog.cc:455] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a6a8211e4e5f43ebb38eb5073b787e21" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a6a8211e4e5f43ebb38eb5073b787e21" member_type: VOTER } }
I20260812 06:20:22.847589 10179 sys_catalog.cc:458] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.847600 10178 sys_catalog.cc:458] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.847919 10183 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:22.848906 10183 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:22.849207  9873 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:22.851634 10183 catalog_manager.cc:1383] Generated new cluster ID: 1f8d5238d79b4acb98c8341806849baf
I20260812 06:20:22.851735 10183 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:22.872910 10183 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:22.873618 10183 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:22.895215 10183 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21: Generated new TSK 0
I20260812 06:20:22.895447 10183 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:22.914323  9873 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.916774 10203 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:20:22.917011  9873 server_base.cc:1061] running on GCE node
W20260812 06:20:22.916849 10205 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:20:22.916863 10202 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:20:22.917366  9873 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.917416  9873 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:20:22.917433  9873 hybrid_clock.cc:648] HybridClock initialized: now 1786515622917433 us; error 0 us; skew 500 ppm
I20260812 06:20:22.918602  9873 webserver.cc:533] Webserver started at http://127.9.164.65:36407/ using document root <none> and password file <none>
I20260812 06:20:22.918843  9873 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.918901  9873 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.918982  9873 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.919409  9873 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/instance:
uuid: "f31870b1df334e179319ec094f03891e"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-ss4n"
I20260812 06:20:22.921090  9873 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:22.922348 10211 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:20:22.922757  9873 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:22.922860  9873 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root
uuid: "f31870b1df334e179319ec094f03891e"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-ss4n"
I20260812 06:20:22.922959  9873 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-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:20:22.948292  9873 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.948743  9873 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.949139  9873 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:22.949728  9873 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:22.949786  9873 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.949846  9873 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:22.949896  9873 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.954784  9873 rpc_server.cc:307] RPC server started. Bound to: 127.9.164.65:42053
I20260812 06:20:22.956445 10284 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.164.65:42053 every 8 connection(s)
I20260812 06:20:22.966079 10286 heartbeater.cc:344] Connected to a master server at 127.9.164.126:38461
I20260812 06:20:22.966270 10286 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:22.966560 10286 heartbeater.cc:507] Master 127.9.164.126:38461 requested a full tablet report, sending...
I20260812 06:20:22.967448 10133 ts_manager.cc:194] Registered new tserver with Master: f31870b1df334e179319ec094f03891e (127.9.164.65:42053)
I20260812 06:20:22.968035  9873 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012229532s
I20260812 06:20:22.968328 10133 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58148
I20260812 06:20:22.976056 10133 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58154:
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:20:22.986286 10242 tablet_service.cc:1511] Processing CreateTablet for tablet 5da0ed5c6c334ecda2b38d096062178b (DEFAULT_TABLE table=heavy-update-compaction-test [id=d0d3b55d7bb94630aff326b88045599f]), partition=
I20260812 06:20:22.986685 10242 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5da0ed5c6c334ecda2b38d096062178b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:22.989287 10305 tablet_bootstrap.cc:492] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Bootstrap starting.
I20260812 06:20:22.990264 10305 tablet_bootstrap.cc:654] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.992003 10305 tablet_bootstrap.cc:492] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: No bootstrap required, opened a new log
I20260812 06:20:22.992113 10305 ts_tablet_manager.cc:1403] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:22.992599 10305 raft_consensus.cc:359] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f31870b1df334e179319ec094f03891e" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 42053 } }
I20260812 06:20:22.992692 10305 raft_consensus.cc:385] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.992738 10305 raft_consensus.cc:740] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f31870b1df334e179319ec094f03891e, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.992897 10305 consensus_queue.cc:260] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [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: "f31870b1df334e179319ec094f03891e" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 42053 } }
I20260812 06:20:22.993028 10305 raft_consensus.cc:399] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.993098 10305 raft_consensus.cc:493] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.993160 10305 raft_consensus.cc:3060] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.994001 10305 raft_consensus.cc:515] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f31870b1df334e179319ec094f03891e" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 42053 } }
I20260812 06:20:22.994161 10305 leader_election.cc:304] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [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: f31870b1df334e179319ec094f03891e; no voters: 
I20260812 06:20:22.994417 10305 leader_election.cc:290] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.994576 10307 raft_consensus.cc:2804] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.994797 10305 ts_tablet_manager.cc:1434] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:22.994831 10286 heartbeater.cc:499] Master 127.9.164.126:38461 was elected leader, sending a full tablet report...
I20260812 06:20:22.994875 10307 raft_consensus.cc:697] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 1 LEADER]: Becoming Leader. State: Replica: f31870b1df334e179319ec094f03891e, State: Running, Role: LEADER
I20260812 06:20:22.995059 10307 consensus_queue.cc:237] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [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: "f31870b1df334e179319ec094f03891e" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 42053 } }
I20260812 06:20:22.996572 10133 catalog_manager.cc:5719] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e reported cstate change: term changed from 0 to 1, leader changed from <none> to f31870b1df334e179319ec094f03891e (127.9.164.65). New cstate: current_term: 1 leader_uuid: "f31870b1df334e179319ec094f03891e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f31870b1df334e179319ec094f03891e" member_type: VOTER last_known_addr { host: "127.9.164.65" port: 42053 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:23.061014  9873 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.016s	sys 0.008s
I20260812 06:20:23.206952 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b): perf score=18.062753
I20260812 06:20:23.391803 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.184s	user 0.123s	sys 0.056s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":148,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":863,"drs_written":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46647,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:23.392701 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling LogGCOp(5da0ed5c6c334ecda2b38d096062178b): free 20743880 bytes of WAL
I20260812 06:20:23.392988 10216 log_reader.cc:385] T 5da0ed5c6c334ecda2b38d096062178b: removed 2 log segments from log reader
I20260812 06:20:23.393039 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000001 (ops 1-6)
I20260812 06:20:23.393075 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000002 (ops 7-11)
I20260812 06:20:23.402639 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: LogGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.010s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:23.403198 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:23.418628 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.015s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.419229 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b): 16411394 bytes on disk
I20260812 06:20:23.419682 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b) 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:20:23.420120 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:23.609753 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.189s	user 0.119s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":384,"lbm_read_time_us":13101,"lbm_reads_lt_1ms":460,"lbm_write_time_us":28763,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":369,"threads_started":5,"update_count":2000}
I20260812 06:20:23.610395 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:23.677117 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.066s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25702,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.677764 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:23.690637 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.691443 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:23.875635 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.184s	user 0.131s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":13601,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35939,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:20:23.876376 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:23.941879 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.065s	user 0.030s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":30187,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.942586 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:23.957173 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.957720 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:24.125761 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.168s	user 0.128s	sys 0.034s 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":823,"lbm_read_time_us":12161,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33247,"lbm_writes_lt_1ms":543,"mutex_wait_us":384,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:20:24.126497 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:24.183158 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.056s	user 0.014s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23762,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.183835 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:24.196851 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.197340 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:24.368852 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.171s	user 0.144s	sys 0.022s 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":560,"lbm_read_time_us":12257,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34155,"lbm_writes_lt_1ms":543,"mutex_wait_us":165,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2500}
I20260812 06:20:24.369673 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=11.118625
I20260812 06:20:24.403198 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.033s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14804,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.403856 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:24.419369 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5807,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.419989 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:24.561226 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.141s	user 0.113s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":9933,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29969,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.562139 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=10.126437
I20260812 06:20:24.627199 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.065s	user 0.031s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18763,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.627930 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:24.648761 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.021s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7980,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.649448 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:24.819871 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.170s	user 0.121s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":12828,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26761,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.820712 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=11.118625
I20260812 06:20:24.857663 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.037s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15897,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.858290 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:24.887449 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.029s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7215,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.887998 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:24.901099 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.901965 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:24.944798 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.043s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":1480,"drs_written":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1920,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":13184}
I20260812 06:20:24.945611 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling LogGCOp(5da0ed5c6c334ecda2b38d096062178b): free 133024360 bytes of WAL
I20260812 06:20:24.945946 10216 log_reader.cc:385] T 5da0ed5c6c334ecda2b38d096062178b: removed 13 log segments from log reader
I20260812 06:20:24.946013 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000003 (ops 12-16)
I20260812 06:20:24.946053 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000004 (ops 17-21)
I20260812 06:20:24.946089 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000005 (ops 22-26)
I20260812 06:20:24.946122 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000006 (ops 27-31)
I20260812 06:20:24.946167 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000007 (ops 32-36)
I20260812 06:20:24.946192 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000008 (ops 37-41)
I20260812 06:20:24.946214 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000009 (ops 42-46)
I20260812 06:20:24.946236 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000010 (ops 47-51)
I20260812 06:20:24.946266 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000011 (ops 52-56)
I20260812 06:20:24.946300 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000012 (ops 57-61)
I20260812 06:20:24.946333 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000013 (ops 62-66)
I20260812 06:20:24.946363 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000014 (ops 67-70)
I20260812 06:20:24.946393 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000015 (ops 71-75)
I20260812 06:20:24.982937 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: LogGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.037s	user 0.000s	sys 0.036s Metrics: {}
I20260812 06:20:24.983402 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b): 493 bytes on disk
I20260812 06:20:24.983908 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.984467 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=3.181125
I20260812 06:20:25.008726 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.024s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7547,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:25.009272 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:25.019367 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3631,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.020038 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:25.286238 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.266s	user 0.160s	sys 0.104s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979848,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":863,"lbm_read_time_us":17494,"lbm_reads_lt_1ms":775,"lbm_write_time_us":46433,"lbm_writes_lt_1ms":743,"mutex_wait_us":67,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":96,"threads_started":1,"update_count":3500}
I20260812 06:20:25.287746 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=16.079562
I20260812 06:20:25.364828 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.077s	user 0.032s	sys 0.036s Metrics: {"bytes_written":18461108,"delete_count":0,"lbm_write_time_us":37203,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":449,"reinsert_count":0,"update_count":2250}
I20260812 06:20:25.365420 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=4.173312
I20260812 06:20:25.387094 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.021s	user 0.011s	sys 0.009s Metrics: {"bytes_written":6153873,"delete_count":0,"lbm_write_time_us":8564,"lbm_writes_lt_1ms":153,"reinsert_count":0,"update_count":750}
I20260812 06:20:25.387828 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:25.623140 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.235s	user 0.155s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":17875,"lbm_reads_lt_1ms":672,"lbm_write_time_us":42074,"lbm_writes_lt_1ms":643,"mutex_wait_us":410,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24576,"update_count":3000}
I20260812 06:20:25.623788 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=15.087375
I20260812 06:20:25.667203 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.043s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":19697,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:25.668192 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:25.687738 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.019s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6483,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.688277 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:25.882679 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.194s	user 0.134s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":13727,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34672,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:20:25.883662 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=15.087375
I20260812 06:20:25.942196 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.058s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":26279,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:25.942723 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:25.961230 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":6792,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:20:25.961848 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:26.154266 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.192s	user 0.124s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815704,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":13986,"lbm_reads_lt_1ms":565,"lbm_write_time_us":34427,"lbm_writes_lt_1ms":544,"mutex_wait_us":116,"peak_mem_usage":63156935,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2505}
I20260812 06:20:26.154996 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:26.217716 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.063s	user 0.039s	sys 0.023s Metrics: {"bytes_written":16368880,"delete_count":0,"lbm_write_time_us":22042,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":1995}
I20260812 06:20:26.218585 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:26.235311 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.235821 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:26.438995 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.203s	user 0.137s	sys 0.059s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24733667,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1234,"lbm_read_time_us":11767,"lbm_reads_lt_1ms":567,"lbm_write_time_us":36903,"lbm_writes_lt_1ms":542,"mutex_wait_us":358,"peak_mem_usage":63074865,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2495}
I20260812 06:20:26.439811 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:26.514006 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.074s	user 0.034s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26879,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.514758 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:26.529027 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.529690 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:26.565749 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":225,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1709,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2187,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1280}
I20260812 06:20:26.566511 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling LogGCOp(5da0ed5c6c334ecda2b38d096062178b): free 111786276 bytes of WAL
I20260812 06:20:26.566769 10216 log_reader.cc:385] T 5da0ed5c6c334ecda2b38d096062178b: removed 11 log segments from log reader
I20260812 06:20:26.566816 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000016 (ops 76-80)
I20260812 06:20:26.566847 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000017 (ops 81-85)
I20260812 06:20:26.566923 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000018 (ops 86-90)
I20260812 06:20:26.566959 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000019 (ops 91-94)
I20260812 06:20:26.567004 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000020 (ops 95-99)
I20260812 06:20:26.567072 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000021 (ops 100-104)
I20260812 06:20:26.567121 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000022 (ops 105-108)
I20260812 06:20:26.567167 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000023 (ops 109-113)
I20260812 06:20:26.567211 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000024 (ops 114-118)
I20260812 06:20:26.567253 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000025 (ops 119-123)
I20260812 06:20:26.567338 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000026 (ops 124-128)
I20260812 06:20:26.594388 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: LogGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:26.594871 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b): 462 bytes on disk
I20260812 06:20:26.595376 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:26.596016 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:26.620707 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.025s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.621407 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling LogGCOp(5da0ed5c6c334ecda2b38d096062178b): free 8767138 bytes of WAL
I20260812 06:20:26.621728 10216 log_reader.cc:385] T 5da0ed5c6c334ecda2b38d096062178b: removed 1 log segments from log reader
I20260812 06:20:26.621812 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000027 (ops 129-133)
I20260812 06:20:26.624039 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: LogGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:26.624468 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:26.638090 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.638695 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:26.924528 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.286s	user 0.170s	sys 0.105s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":797,"lbm_read_time_us":19248,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44789,"lbm_writes_lt_1ms":743,"mutex_wait_us":477,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:20:26.927150 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=18.063937
I20260812 06:20:27.011606 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.084s	user 0.051s	sys 0.020s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":34128,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:27.012215 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:27.025322 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.025899 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:27.277878 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.252s	user 0.153s	sys 0.086s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":442,"lbm_read_time_us":16255,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39587,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":49408,"update_count":3000}
I20260812 06:20:27.278635 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=18.063937
I20260812 06:20:27.360124 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.081s	user 0.043s	sys 0.033s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":34749,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:27.360737 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:27.373677 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.374282 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:27.596235 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.222s	user 0.140s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1514,"lbm_read_time_us":14796,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38627,"lbm_writes_lt_1ms":643,"mutex_wait_us":570,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":3000}
I20260812 06:20:27.596932 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:27.652128 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.055s	user 0.012s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24353,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.653105 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:27.672286 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.672950 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:27.864043 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.191s	user 0.135s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1291,"lbm_read_time_us":13865,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34021,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:20:27.864825 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:27.928939 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.064s	user 0.026s	sys 0.034s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":29874,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.929618 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:27.963148 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.033s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.964040 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:27.985302 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.021s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.986022 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:28.232586 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.246s	user 0.181s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1428,"lbm_read_time_us":14958,"lbm_reads_lt_1ms":665,"lbm_write_time_us":37758,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3000}
I20260812 06:20:28.233527 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=12.110812
I20260812 06:20:28.281961 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.048s	user 0.036s	sys 0.012s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":21256,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:20:28.282944 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.196750
I20260812 06:20:28.303604 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":5880,"lbm_writes_lt_1ms":73,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":350}
I20260812 06:20:28.304198 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:28.345400 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushMRSOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.041s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1418,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1613,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:28.346297 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling LogGCOp(5da0ed5c6c334ecda2b38d096062178b): free 108535689 bytes of WAL
I20260812 06:20:28.346561 10216 log_reader.cc:385] T 5da0ed5c6c334ecda2b38d096062178b: removed 11 log segments from log reader
I20260812 06:20:28.346629 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000028 (ops 134-138)
I20260812 06:20:28.346726 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000029 (ops 139-143)
I20260812 06:20:28.346799 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000030 (ops 144-148)
I20260812 06:20:28.346877 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000031 (ops 149-153)
I20260812 06:20:28.346921 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000032 (ops 154-158)
I20260812 06:20:28.346971 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000033 (ops 159-162)
I20260812 06:20:28.347023 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000034 (ops 163-167)
I20260812 06:20:28.347072 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000035 (ops 168-172)
I20260812 06:20:28.347142 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000036 (ops 173-176)
I20260812 06:20:28.347193 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000037 (ops 177-181)
I20260812 06:20:28.347241 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000038 (ops 182-186)
I20260812 06:20:28.373512 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: LogGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.027s	user 0.001s	sys 0.022s Metrics: {}
I20260812 06:20:28.374243 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b): 463 bytes on disk
I20260812 06:20:28.375167 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: UndoDeltaBlockGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.376343 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:28.425316 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.048s	user 0.018s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":18636,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.426129 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling LogGCOp(5da0ed5c6c334ecda2b38d096062178b): free 12017955 bytes of WAL
I20260812 06:20:28.426445 10216 log_reader.cc:385] T 5da0ed5c6c334ecda2b38d096062178b: removed 1 log segments from log reader
I20260812 06:20:28.426505 10216 log.cc:1079] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: Deleting log segment in path: /tmp/dist-test-task03nq5M/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616722756-9873-0/minicluster-data/ts-0-root/wals/5da0ed5c6c334ecda2b38d096062178b/wal-000000039 (ops 187-191)
I20260812 06:20:28.430318 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: LogGCOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:28.430991 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:28.449199 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.018s	user 0.007s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.450382 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:28.686771 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.236s	user 0.137s	sys 0.099s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":617,"lbm_read_time_us":18036,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39722,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16640,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:20:28.689657 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=14.095187
I20260812 06:20:28.760449  9873 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.699s	user 2.003s	sys 0.252s
I20260812 06:20:28.764444 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.074s	user 0.028s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27339,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.765048 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b): perf score=2.188937
I20260812 06:20:28.782886 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: FlushDeltaMemStoresOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:20:28.783663 10287 maintenance_manager.cc:419] P f31870b1df334e179319ec094f03891e: Scheduling MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b): perf score=1.000000
I20260812 06:20:28.841691  9873 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.003s	sys 0.000s
I20260812 06:20:28.842311  9873 tablet_server.cc:179] TabletServer@127.9.164.65:0 shutting down...
I20260812 06:20:28.922119 10216 maintenance_manager.cc:643] P f31870b1df334e179319ec094f03891e: MajorDeltaCompactionOp(5da0ed5c6c334ecda2b38d096062178b) complete. Timing: real 0.138s	user 0.114s	sys 0.023s Metrics: {"cfile_cache_hit":248,"cfile_cache_hit_bytes":10135084,"cfile_cache_miss":284,"cfile_cache_miss_bytes":14639604,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":452,"lbm_read_time_us":6982,"lbm_reads_lt_1ms":316,"lbm_write_time_us":26964,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":129920,"update_count":2500}
I20260812 06:20:28.923055  9873 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:28.923727  9873 tablet_replica.cc:333] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e: stopping tablet replica
I20260812 06:20:28.923934  9873 raft_consensus.cc:2243] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.924142  9873 raft_consensus.cc:2272] T 5da0ed5c6c334ecda2b38d096062178b P f31870b1df334e179319ec094f03891e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.931457  9873 tablet_server.cc:196] TabletServer@127.9.164.65:0 shutdown complete.
I20260812 06:20:28.969779  9873 master.cc:562] Master@127.9.164.126:38461 shutting down...
I20260812 06:20:28.973887  9873 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.974114  9873 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.974174  9873 tablet_replica.cc:333] T 00000000000000000000000000000000 P a6a8211e4e5f43ebb38eb5073b787e21: stopping tablet replica
I20260812 06:20:28.987200  9873 master.cc:584] Master@127.9.164.126:38461 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6299 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12349 ms total)

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