[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:42.027494 31455 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.183.254:46541
I20260812 06:19:42.028617 31455 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:42.029268 31455 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:42.036515 31455 server_base.cc:1061] running on GCE node
W20260812 06:19:42.036435 31462 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.036435 31461 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.036835 31465 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.037427 31455 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.037536 31455 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:42.037572 31455 hybrid_clock.cc:648] HybridClock initialized: now 1786515582037571 us; error 0 us; skew 500 ppm
I20260812 06:19:42.039793 31455 webserver.cc:533] Webserver started at http://127.30.183.254:32775/ using document root <none> and password file <none>
I20260812 06:19:42.040386 31455 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.040454 31455 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.040665 31455 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.042549 31455 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/master-0-root/instance:
uuid: "a40c78c8425f4372aacb4592590fa190"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-5l3k"
I20260812 06:19:42.046746 31455 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:19:42.049350 31470 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.050675 31455 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:42.050832 31455 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/master-0-root
uuid: "a40c78c8425f4372aacb4592590fa190"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-5l3k"
I20260812 06:19:42.050956 31455 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:42.081808 31455 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.082719 31455 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:42.082942 31455 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.091248 31455 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.254:46541
I20260812 06:19:42.091252 31537 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.254:46541 every 8 connection(s)
I20260812 06:19:42.093736 31539 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.099669 31539 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190: Bootstrap starting.
I20260812 06:19:42.102267 31539 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.103492 31539 log.cc:826] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:42.105417 31539 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190: No bootstrap required, opened a new log
I20260812 06:19:42.108486 31539 raft_consensus.cc:359] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40c78c8425f4372aacb4592590fa190" member_type: VOTER }
I20260812 06:19:42.108681 31539 raft_consensus.cc:385] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.108779 31539 raft_consensus.cc:740] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a40c78c8425f4372aacb4592590fa190, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.109592 31539 consensus_queue.cc:260] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [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: "a40c78c8425f4372aacb4592590fa190" member_type: VOTER }
I20260812 06:19:42.109766 31539 raft_consensus.cc:399] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.109906 31539 raft_consensus.cc:493] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.110061 31539 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.111066 31539 raft_consensus.cc:515] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40c78c8425f4372aacb4592590fa190" member_type: VOTER }
I20260812 06:19:42.111572 31539 leader_election.cc:304] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [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: a40c78c8425f4372aacb4592590fa190; no voters: 
I20260812 06:19:42.111948 31539 leader_election.cc:290] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.112164 31544 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.112450 31544 raft_consensus.cc:697] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 1 LEADER]: Becoming Leader. State: Replica: a40c78c8425f4372aacb4592590fa190, State: Running, Role: LEADER
I20260812 06:19:42.112860 31544 consensus_queue.cc:237] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [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: "a40c78c8425f4372aacb4592590fa190" member_type: VOTER }
I20260812 06:19:42.113149 31539 sys_catalog.cc:565] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:42.114905 31545 sys_catalog.cc:455] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a40c78c8425f4372aacb4592590fa190" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40c78c8425f4372aacb4592590fa190" member_type: VOTER } }
I20260812 06:19:42.115051 31545 sys_catalog.cc:458] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.115403 31546 sys_catalog.cc:455] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a40c78c8425f4372aacb4592590fa190. Latest consensus state: current_term: 1 leader_uuid: "a40c78c8425f4372aacb4592590fa190" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40c78c8425f4372aacb4592590fa190" member_type: VOTER } }
I20260812 06:19:42.115483 31546 sys_catalog.cc:458] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.115588 31455 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:42.115466 31557 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:42.117859 31557 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:42.123093 31557 catalog_manager.cc:1383] Generated new cluster ID: f209075ba63d4974a0f502f555a9eaaf
I20260812 06:19:42.123185 31557 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:42.143713 31557 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:42.144702 31557 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:42.152624 31557 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190: Generated new TSK 0
I20260812 06:19:42.153352 31557 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:42.180615 31455 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:42.184195 31565 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.184198 31567 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.184376 31455 server_base.cc:1061] running on GCE node
W20260812 06:19:42.184198 31564 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.184783 31455 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.184829 31455 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:42.184845 31455 hybrid_clock.cc:648] HybridClock initialized: now 1786515582184846 us; error 0 us; skew 500 ppm
I20260812 06:19:42.185845 31455 webserver.cc:533] Webserver started at http://127.30.183.193:35071/ using document root <none> and password file <none>
I20260812 06:19:42.186045 31455 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.186100 31455 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.186218 31455 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.186717 31455 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/instance:
uuid: "d2a15fce8b604b76966f47ed2f50c620"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-5l3k"
I20260812 06:19:42.188349 31455 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:42.189450 31573 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.189735 31455 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:42.189831 31455 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root
uuid: "d2a15fce8b604b76966f47ed2f50c620"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-5l3k"
I20260812 06:19:42.189934 31455 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:42.206936 31455 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.207535 31455 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.208158 31455 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:42.209081 31455 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:42.209160 31455 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.209242 31455 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:42.209290 31455 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.216766 31455 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.193:46315
I20260812 06:19:42.216805 31646 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.193:46315 every 8 connection(s)
I20260812 06:19:42.236805 31647 heartbeater.cc:344] Connected to a master server at 127.30.183.254:46541
I20260812 06:19:42.237082 31647 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:42.237558 31647 heartbeater.cc:507] Master 127.30.183.254:46541 requested a full tablet report, sending...
I20260812 06:19:42.239586 31494 ts_manager.cc:194] Registered new tserver with Master: d2a15fce8b604b76966f47ed2f50c620 (127.30.183.193:46315)
I20260812 06:19:42.240198 31455 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.022706255s
I20260812 06:19:42.241170 31494 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44656
I20260812 06:19:42.251935 31494 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44664:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:42.269065 31604 tablet_service.cc:1511] Processing CreateTablet for tablet e898bd73b3684aa6bee1117f32d89097 (DEFAULT_TABLE table=heavy-update-compaction-test [id=974bc849b11a49e58e755b6d46aaf95b]), partition=
I20260812 06:19:42.269598 31604 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e898bd73b3684aa6bee1117f32d89097. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.272125 31660 tablet_bootstrap.cc:492] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Bootstrap starting.
I20260812 06:19:42.273556 31660 tablet_bootstrap.cc:654] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.274942 31660 tablet_bootstrap.cc:492] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: No bootstrap required, opened a new log
I20260812 06:19:42.275099 31660 ts_tablet_manager.cc:1403] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:42.275736 31660 raft_consensus.cc:359] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2a15fce8b604b76966f47ed2f50c620" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 46315 } }
I20260812 06:19:42.275898 31660 raft_consensus.cc:385] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.275949 31660 raft_consensus.cc:740] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d2a15fce8b604b76966f47ed2f50c620, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.276105 31660 consensus_queue.cc:260] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [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: "d2a15fce8b604b76966f47ed2f50c620" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 46315 } }
I20260812 06:19:42.276202 31660 raft_consensus.cc:399] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.276250 31660 raft_consensus.cc:493] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.276306 31660 raft_consensus.cc:3060] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.277083 31660 raft_consensus.cc:515] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2a15fce8b604b76966f47ed2f50c620" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 46315 } }
I20260812 06:19:42.277248 31660 leader_election.cc:304] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [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: d2a15fce8b604b76966f47ed2f50c620; no voters: 
I20260812 06:19:42.277513 31660 leader_election.cc:290] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.277631 31662 raft_consensus.cc:2804] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.277913 31662 raft_consensus.cc:697] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 1 LEADER]: Becoming Leader. State: Replica: d2a15fce8b604b76966f47ed2f50c620, State: Running, Role: LEADER
I20260812 06:19:42.278187 31647 heartbeater.cc:499] Master 127.30.183.254:46541 was elected leader, sending a full tablet report...
I20260812 06:19:42.278124 31662 consensus_queue.cc:237] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [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: "d2a15fce8b604b76966f47ed2f50c620" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 46315 } }
I20260812 06:19:42.277933 31660 ts_tablet_manager.cc:1434] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:42.281028 31494 catalog_manager.cc:5719] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 reported cstate change: term changed from 0 to 1, leader changed from <none> to d2a15fce8b604b76966f47ed2f50c620 (127.30.183.193). New cstate: current_term: 1 leader_uuid: "d2a15fce8b604b76966f47ed2f50c620" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2a15fce8b604b76966f47ed2f50c620" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 46315 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:42.342653 31455 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.022s	sys 0.004s
I20260812 06:19:42.467976 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushMRSOp(e898bd73b3684aa6bee1117f32d89097): perf score=15.086190
I20260812 06:19:42.643662 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushMRSOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.175s	user 0.136s	sys 0.033s Metrics: {"bytes_written":13661280,"cfile_init":1,"compiler_manager_pool.queue_time_us":302,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1181,"drs_written":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42358,"lbm_writes_lt_1ms":690,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":176000,"thread_start_us":127,"threads_started":1,"update_count":1665}
I20260812 06:19:42.644845 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097): 12308958 bytes on disk
I20260812 06:19:42.645598 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.646032 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=3.181125
I20260812 06:19:42.661641 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4389833,"delete_count":0,"lbm_write_time_us":6206,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:19:42.662132 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling LogGCOp(e898bd73b3684aa6bee1117f32d89097): free 11976772 bytes of WAL
I20260812 06:19:42.662423 31578 log_reader.cc:385] T e898bd73b3684aa6bee1117f32d89097: removed 1 log segments from log reader
I20260812 06:19:42.662528 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000001 (ops 1-6)
I20260812 06:19:42.665738 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: LogGCOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:42.666103 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.196750
I20260812 06:19:42.676223 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":3562,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:19:42.676708 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:42.863615 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.187s	user 0.124s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733802,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":830,"lbm_read_time_us":13546,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29753,"lbm_writes_lt_1ms":543,"mutex_wait_us":167,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":348,"threads_started":5,"update_count":2500}
I20260812 06:19:42.864183 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=11.118625
I20260812 06:19:42.900339 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15280,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:42.901114 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:42.919811 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.018s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5850,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.920379 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:43.055796 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.135s	user 0.111s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1051,"lbm_read_time_us":9167,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27610,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:19:43.059669 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=11.118625
I20260812 06:19:43.092419 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.032s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13508,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:43.093106 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:43.112468 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5258,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.113181 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:43.240594 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.127s	user 0.107s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":990,"lbm_read_time_us":7646,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23425,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2000}
I20260812 06:19:43.241859 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:43.284304 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.042s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20650,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.284962 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:43.301083 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.301764 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:43.533649 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.232s	user 0.167s	sys 0.063s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":993,"lbm_read_time_us":9227,"lbm_reads_lt_1ms":472,"lbm_write_time_us":57203,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:43.535386 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:43.654675 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.119s	user 0.055s	sys 0.062s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":40175,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:19:43.659161 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:43.698618 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.038s	user 0.026s	sys 0.011s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":15527,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":475}
I20260812 06:19:43.699671 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:43.958734 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.259s	user 0.178s	sys 0.081s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631308,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":416,"lbm_read_time_us":15905,"lbm_reads_lt_1ms":472,"lbm_write_time_us":52224,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.959764 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:44.033663 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.074s	user 0.044s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":32442,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.034842 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:44.065446 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.030s	user 0.009s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.066304 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:44.280951 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.214s	user 0.145s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1059,"lbm_read_time_us":16503,"lbm_reads_lt_1ms":464,"lbm_write_time_us":44661,"lbm_writes_lt_1ms":443,"mutex_wait_us":472,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2000}
I20260812 06:19:44.282209 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=11.118625
I20260812 06:19:44.340503 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.058s	user 0.024s	sys 0.031s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":26748,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.341171 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:44.364916 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.024s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5151,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.365402 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:44.376343 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.376893 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushMRSOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:44.409821 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushMRSOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":269,"dirs.run_wall_time_us":1376,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2267,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:44.410769 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling LogGCOp(e898bd73b3684aa6bee1117f32d89097): free 129320469 bytes of WAL
I20260812 06:19:44.411015 31578 log_reader.cc:385] T e898bd73b3684aa6bee1117f32d89097: removed 13 log segments from log reader
I20260812 06:19:44.411085 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000002 (ops 7-11)
I20260812 06:19:44.411139 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000003 (ops 12-16)
I20260812 06:19:44.411197 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000004 (ops 17-21)
I20260812 06:19:44.411238 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000005 (ops 22-26)
I20260812 06:19:44.411274 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000006 (ops 27-30)
I20260812 06:19:44.411310 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000007 (ops 31-35)
I20260812 06:19:44.411347 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000008 (ops 36-40)
I20260812 06:19:44.411384 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000009 (ops 41-44)
I20260812 06:19:44.411420 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000010 (ops 45-49)
I20260812 06:19:44.411458 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000011 (ops 50-54)
I20260812 06:19:44.411494 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000012 (ops 55-59)
I20260812 06:19:44.411528 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000013 (ops 60-64)
I20260812 06:19:44.411568 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000014 (ops 65-69)
I20260812 06:19:44.445365 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: LogGCOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.034s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:19:44.445825 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=3.181125
I20260812 06:19:44.463975 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7086,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:44.464469 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:44.474308 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3669,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.474871 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:44.666433 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.191s	user 0.151s	sys 0.040s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938882,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":580,"lbm_read_time_us":13850,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37878,"lbm_writes_lt_1ms":743,"mutex_wait_us":57,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17024,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:19:44.667363 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=14.095187
I20260812 06:19:44.722193 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.055s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23837,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.722898 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097): 473 bytes on disk
I20260812 06:19:44.723501 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.724015 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:44.748992 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.025s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.749614 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:44.938205 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.188s	user 0.136s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":675,"lbm_read_time_us":12969,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31024,"lbm_writes_lt_1ms":543,"mutex_wait_us":118,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:44.939030 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=14.095187
I20260812 06:19:44.991886 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.053s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24826,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.992372 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:45.005596 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.006229 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:45.161262 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.155s	user 0.106s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":979,"lbm_read_time_us":9763,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31048,"lbm_writes_lt_1ms":543,"mutex_wait_us":134,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:19:45.162132 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=11.118625
I20260812 06:19:45.201964 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.040s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17393,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:45.202617 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:45.216449 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5039,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.217139 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:45.348774 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.131s	user 0.112s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":68,"lbm_read_time_us":8432,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26384,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:19:45.350093 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:45.385540 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.035s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12430563,"delete_count":0,"lbm_write_time_us":15237,"lbm_writes_lt_1ms":306,"mutex_wait_us":270,"reinsert_count":0,"update_count":1515}
I20260812 06:19:45.386142 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:45.402173 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":6290,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:45.402738 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:45.541249 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.138s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":9765,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26961,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:45.542092 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:45.598227 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.056s	user 0.028s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18091,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.598891 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:45.609954 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.610594 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:45.772738 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.162s	user 0.113s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":11131,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27893,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.773591 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:45.822186 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.048s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15731,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.822801 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:45.835366 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.836053 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushMRSOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:45.870698 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushMRSOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.034s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":310,"dirs.run_wall_time_us":1636,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1921,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:45.871484 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling LogGCOp(e898bd73b3684aa6bee1117f32d89097): free 115943241 bytes of WAL
I20260812 06:19:45.871766 31578 log_reader.cc:385] T e898bd73b3684aa6bee1117f32d89097: removed 11 log segments from log reader
I20260812 06:19:45.871815 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000015 (ops 70-74)
I20260812 06:19:45.871874 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000016 (ops 75-79)
I20260812 06:19:45.871923 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000017 (ops 80-84)
I20260812 06:19:45.871999 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000018 (ops 85-89)
I20260812 06:19:45.872080 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000019 (ops 90-94)
I20260812 06:19:45.872126 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000020 (ops 95-99)
I20260812 06:19:45.872196 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000021 (ops 100-104)
I20260812 06:19:45.872241 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000022 (ops 105-109)
I20260812 06:19:45.872283 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000023 (ops 110-114)
I20260812 06:19:45.872328 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000024 (ops 115-119)
I20260812 06:19:45.872372 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000025 (ops 120-124)
I20260812 06:19:45.900520 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: LogGCOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:45.901052 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097): 448 bytes on disk
I20260812 06:19:45.901774 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:45.902338 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=4.173312
I20260812 06:19:45.929322 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.027s	user 0.017s	sys 0.007s Metrics: {"bytes_written":5743633,"delete_count":0,"lbm_write_time_us":6819,"lbm_writes_lt_1ms":143,"reinsert_count":0,"update_count":700}
I20260812 06:19:45.929889 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.196750
I20260812 06:19:45.937505 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.007s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":2597,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:19:45.938019 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:46.146749 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.209s	user 0.141s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":249,"lbm_read_time_us":14257,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33668,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:46.147588 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=14.095187
I20260812 06:19:46.217916 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.070s	user 0.023s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19189,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.218740 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:46.237454 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.238137 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:46.430873 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.192s	user 0.149s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1094,"lbm_read_time_us":13775,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33531,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":80,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.431572 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=14.095187
I20260812 06:19:46.481684 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.050s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409908,"delete_count":0,"lbm_write_time_us":20951,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.482184 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:46.493049 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.493845 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:46.681061 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.187s	user 0.095s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733729,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":963,"lbm_read_time_us":11138,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31874,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:19:46.681627 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=14.095187
I20260812 06:19:46.734031 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.052s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21379,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.734540 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:46.746686 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.747303 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:46.910637 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.163s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":419,"lbm_read_time_us":10345,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31849,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:19:46.911540 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=11.118625
I20260812 06:19:46.953560 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.042s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18131,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.954376 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:46.970773 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5667,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.971350 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:47.106971 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.135s	user 0.099s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":10072,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27080,"lbm_writes_lt_1ms":443,"mutex_wait_us":107,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:19:47.107697 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:47.152719 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.045s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15907,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.153424 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:47.166930 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.167913 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:47.300815 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.133s	user 0.098s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":735,"lbm_read_time_us":7834,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26545,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:47.302132 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:47.344121 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.042s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13078,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.344683 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:47.361310 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.361938 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushMRSOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:47.408972 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushMRSOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.047s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1547,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1825,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:47.409755 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling LogGCOp(e898bd73b3684aa6bee1117f32d89097): free 120553625 bytes of WAL
I20260812 06:19:47.410007 31578 log_reader.cc:385] T e898bd73b3684aa6bee1117f32d89097: removed 12 log segments from log reader
I20260812 06:19:47.410054 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000026 (ops 125-129)
I20260812 06:19:47.410084 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000027 (ops 130-134)
I20260812 06:19:47.410152 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000028 (ops 135-139)
I20260812 06:19:47.410187 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000029 (ops 140-144)
I20260812 06:19:47.410229 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000030 (ops 145-148)
I20260812 06:19:47.410248 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000031 (ops 149-153)
I20260812 06:19:47.410306 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000032 (ops 154-158)
I20260812 06:19:47.410347 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000033 (ops 159-163)
I20260812 06:19:47.410389 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000034 (ops 164-168)
I20260812 06:19:47.410431 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000035 (ops 169-173)
I20260812 06:19:47.410470 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000036 (ops 174-178)
I20260812 06:19:47.410537 31578 log.cc:1079] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e898bd73b3684aa6bee1117f32d89097/wal-000000037 (ops 179-182)
I20260812 06:19:47.435601 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: LogGCOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:47.436036 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097): 461 bytes on disk
I20260812 06:19:47.436635 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: UndoDeltaBlockGCOp(e898bd73b3684aa6bee1117f32d89097) 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:19:47.437320 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:47.453958 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.016s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":4645,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:19:47.454561 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:47.465369 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4061633,"delete_count":0,"lbm_write_time_us":4053,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:47.465919 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:47.675612 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.209s	user 0.130s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":477,"lbm_read_time_us":15510,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33541,"lbm_writes_lt_1ms":643,"mutex_wait_us":256,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:19:47.676206 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=14.095187
I20260812 06:19:47.746775 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.070s	user 0.039s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27383,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.747267 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=2.188937
I20260812 06:19:47.759059 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.759847 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097): perf score=1.000000
I20260812 06:19:47.895335 31455 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.553s	user 1.996s	sys 0.165s
I20260812 06:19:47.926095 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: MajorDeltaCompactionOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.166s	user 0.104s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":12730,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28446,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:47.926697 31648 maintenance_manager.cc:419] P d2a15fce8b604b76966f47ed2f50c620: Scheduling FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097): perf score=10.126437
I20260812 06:19:47.952028 31455 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.003s	sys 0.000s
I20260812 06:19:47.952798 31455 tablet_server.cc:179] TabletServer@127.30.183.193:0 shutting down...
I20260812 06:19:47.963560 31578 maintenance_manager.cc:643] P d2a15fce8b604b76966f47ed2f50c620: FlushDeltaMemStoresOp(e898bd73b3684aa6bee1117f32d89097) complete. Timing: real 0.037s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16406,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.964241 31455 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:47.964627 31455 tablet_replica.cc:333] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620: stopping tablet replica
I20260812 06:19:47.964991 31455 raft_consensus.cc:2243] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.965277 31455 raft_consensus.cc:2272] T e898bd73b3684aa6bee1117f32d89097 P d2a15fce8b604b76966f47ed2f50c620 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.990713 31455 tablet_server.cc:196] TabletServer@127.30.183.193:0 shutdown complete.
I20260812 06:19:47.996238 31455 master.cc:562] Master@127.30.183.254:46541 shutting down...
I20260812 06:19:48.001165 31455 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:48.001412 31455 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:48.001528 31455 tablet_replica.cc:333] T 00000000000000000000000000000000 P a40c78c8425f4372aacb4592590fa190: stopping tablet replica
I20260812 06:19:48.014568 31455 master.cc:584] Master@127.30.183.254:46541 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6084 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:48.111681 31455 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.183.254:42887
I20260812 06:19:48.112217 31455 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:48.114581 31686 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:19:48.114637 31683 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.114622 31455 server_base.cc:1061] running on GCE node
W20260812 06:19:48.114583 31684 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.114981 31455 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:48.115028 31455 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:48.115043 31455 hybrid_clock.cc:648] HybridClock initialized: now 1786515588115044 us; error 0 us; skew 500 ppm
I20260812 06:19:48.115898 31455 webserver.cc:533] Webserver started at http://127.30.183.254:46015/ using document root <none> and password file <none>
I20260812 06:19:48.116101 31455 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:48.116153 31455 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:48.116289 31455 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:48.116717 31455 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/master-0-root/instance:
uuid: "1d18470217e24191b0e6fe70ea3c0ab4"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-5l3k"
I20260812 06:19:48.118309 31455 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:48.119374 31693 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.119679 31455 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:48.119755 31455 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/master-0-root
uuid: "1d18470217e24191b0e6fe70ea3c0ab4"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-5l3k"
I20260812 06:19:48.119863 31455 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:48.132863 31455 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:48.133373 31455 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:48.137916 31455 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.254:42887
I20260812 06:19:48.142145 31757 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:48.146190 31756 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.254:42887 every 8 connection(s)
I20260812 06:19:48.146754 31757 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4: Bootstrap starting.
I20260812 06:19:48.147640 31757 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:48.148737 31757 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4: No bootstrap required, opened a new log
I20260812 06:19:48.149170 31757 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d18470217e24191b0e6fe70ea3c0ab4" member_type: VOTER }
I20260812 06:19:48.149283 31757 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:48.149334 31757 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1d18470217e24191b0e6fe70ea3c0ab4, State: Initialized, Role: FOLLOWER
I20260812 06:19:48.149531 31757 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [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: "1d18470217e24191b0e6fe70ea3c0ab4" member_type: VOTER }
I20260812 06:19:48.149642 31757 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:48.149690 31757 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:48.149744 31757 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:48.150557 31757 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d18470217e24191b0e6fe70ea3c0ab4" member_type: VOTER }
I20260812 06:19:48.150718 31757 leader_election.cc:304] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [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: 1d18470217e24191b0e6fe70ea3c0ab4; no voters: 
I20260812 06:19:48.150943 31757 leader_election.cc:290] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:48.151177 31760 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:48.151413 31757 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:48.151432 31760 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 1 LEADER]: Becoming Leader. State: Replica: 1d18470217e24191b0e6fe70ea3c0ab4, State: Running, Role: LEADER
I20260812 06:19:48.151563 31760 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [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: "1d18470217e24191b0e6fe70ea3c0ab4" member_type: VOTER }
I20260812 06:19:48.152040 31763 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1d18470217e24191b0e6fe70ea3c0ab4. Latest consensus state: current_term: 1 leader_uuid: "1d18470217e24191b0e6fe70ea3c0ab4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d18470217e24191b0e6fe70ea3c0ab4" member_type: VOTER } }
I20260812 06:19:48.152199 31763 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:48.152061 31761 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1d18470217e24191b0e6fe70ea3c0ab4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1d18470217e24191b0e6fe70ea3c0ab4" member_type: VOTER } }
I20260812 06:19:48.152366 31761 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:48.152805 31772 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:48.153643 31772 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:48.153857 31455 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:48.155712 31772 catalog_manager.cc:1383] Generated new cluster ID: 4e02e98bf53749429df508c416750dd3
I20260812 06:19:48.155777 31772 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:48.165846 31772 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:48.166429 31772 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:48.171581 31772 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4: Generated new TSK 0
I20260812 06:19:48.171800 31772 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:48.186604 31455 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:48.188879 31783 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:48.188944 31784 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.189028 31455 server_base.cc:1061] running on GCE node
W20260812 06:19:48.188938 31786 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.189428 31455 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:48.189488 31455 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:48.189508 31455 hybrid_clock.cc:648] HybridClock initialized: now 1786515588189508 us; error 0 us; skew 500 ppm
I20260812 06:19:48.190577 31455 webserver.cc:533] Webserver started at http://127.30.183.193:33405/ using document root <none> and password file <none>
I20260812 06:19:48.190775 31455 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:48.190850 31455 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:48.190948 31455 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:48.191438 31455 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/instance:
uuid: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-5l3k"
I20260812 06:19:48.193225 31455 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:48.194396 31791 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.194767 31455 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:48.194839 31455 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root
uuid: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-5l3k"
I20260812 06:19:48.194940 31455 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:48.205122 31455 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:48.205592 31455 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:48.205945 31455 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:48.206537 31455 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:48.206601 31455 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.206664 31455 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:48.206713 31455 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.211439 31455 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.193:44985
I20260812 06:19:48.213471 31869 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.193:44985 every 8 connection(s)
I20260812 06:19:48.222678 31870 heartbeater.cc:344] Connected to a master server at 127.30.183.254:42887
I20260812 06:19:48.222836 31870 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:48.223143 31870 heartbeater.cc:507] Master 127.30.183.254:42887 requested a full tablet report, sending...
I20260812 06:19:48.223875 31713 ts_manager.cc:194] Registered new tserver with Master: f29ee03d8f8c4dcd80cbaf4c02ab5b0a (127.30.183.193:44985)
I20260812 06:19:48.224645 31713 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60972
I20260812 06:19:48.224675 31455 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012219487s
I20260812 06:19:48.232348 31713 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60986:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:48.241369 31825 tablet_service.cc:1511] Processing CreateTablet for tablet e0b2119aa6c540a199263e2561d65445 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2b96f660f0654d7aa6cf3a5522d77db5]), partition=
I20260812 06:19:48.241634 31825 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e0b2119aa6c540a199263e2561d65445. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:48.243954 31884 tablet_bootstrap.cc:492] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Bootstrap starting.
I20260812 06:19:48.244848 31884 tablet_bootstrap.cc:654] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:48.246075 31884 tablet_bootstrap.cc:492] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: No bootstrap required, opened a new log
I20260812 06:19:48.246207 31884 ts_tablet_manager.cc:1403] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:48.246742 31884 raft_consensus.cc:359] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 44985 } }
I20260812 06:19:48.246865 31884 raft_consensus.cc:385] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:48.246899 31884 raft_consensus.cc:740] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f29ee03d8f8c4dcd80cbaf4c02ab5b0a, State: Initialized, Role: FOLLOWER
I20260812 06:19:48.247035 31884 consensus_queue.cc:260] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [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: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 44985 } }
I20260812 06:19:48.247164 31884 raft_consensus.cc:399] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:48.247216 31884 raft_consensus.cc:493] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:48.247268 31884 raft_consensus.cc:3060] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:48.248044 31884 raft_consensus.cc:515] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 44985 } }
I20260812 06:19:48.248170 31884 leader_election.cc:304] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [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: f29ee03d8f8c4dcd80cbaf4c02ab5b0a; no voters: 
I20260812 06:19:48.248334 31884 leader_election.cc:290] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:48.248482 31886 raft_consensus.cc:2804] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:48.248646 31884 ts_tablet_manager.cc:1434] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:48.248711 31886 raft_consensus.cc:697] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 1 LEADER]: Becoming Leader. State: Replica: f29ee03d8f8c4dcd80cbaf4c02ab5b0a, State: Running, Role: LEADER
I20260812 06:19:48.248711 31870 heartbeater.cc:499] Master 127.30.183.254:42887 was elected leader, sending a full tablet report...
I20260812 06:19:48.248947 31886 consensus_queue.cc:237] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [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: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 44985 } }
I20260812 06:19:48.250303 31713 catalog_manager.cc:5719] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a reported cstate change: term changed from 0 to 1, leader changed from <none> to f29ee03d8f8c4dcd80cbaf4c02ab5b0a (127.30.183.193). New cstate: current_term: 1 leader_uuid: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f29ee03d8f8c4dcd80cbaf4c02ab5b0a" member_type: VOTER last_known_addr { host: "127.30.183.193" port: 44985 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:48.312371 31455 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.016s	sys 0.007s
I20260812 06:19:48.464015 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushMRSOp(e0b2119aa6c540a199263e2561d65445): perf score=19.054940
I20260812 06:19:48.624325 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushMRSOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.160s	user 0.118s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1043,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42243,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:48.625013 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling LogGCOp(e0b2119aa6c540a199263e2561d65445): free 20743880 bytes of WAL
I20260812 06:19:48.625290 31798 log_reader.cc:385] T e0b2119aa6c540a199263e2561d65445: removed 2 log segments from log reader
I20260812 06:19:48.625365 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000001 (ops 1-6)
I20260812 06:19:48.625422 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000002 (ops 7-11)
I20260812 06:19:48.629788 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: LogGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:48.630347 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445): 16411395 bytes on disk
I20260812 06:19:48.630842 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.631253 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:48.648857 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.649506 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:48.801218 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.151s	user 0.105s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":871,"lbm_read_time_us":10089,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28461,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":382,"threads_started":5,"update_count":2000}
I20260812 06:19:48.801816 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=11.118625
I20260812 06:19:48.851922 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.050s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17396,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:48.852701 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:48.865451 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5004,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.865923 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:49.018710 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.153s	user 0.088s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":731,"lbm_read_time_us":11056,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24755,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:19:49.019579 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=10.126437
I20260812 06:19:49.061874 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.042s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":17905,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.062407 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:49.079232 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.079794 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:49.210577 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.131s	user 0.095s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672282,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":10701,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23163,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:19:49.211136 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=10.126437
I20260812 06:19:49.255440 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.044s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15924,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.255931 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:49.267082 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.267791 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:49.398051 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.130s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":406,"lbm_read_time_us":10138,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24750,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":2000}
I20260812 06:19:49.398792 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=10.126437
I20260812 06:19:49.437963 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.039s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15351,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.438608 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:49.453693 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.454182 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:49.583254 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.129s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":8698,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25862,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:19:49.583976 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=10.126437
I20260812 06:19:49.636353 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.052s	user 0.022s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15081,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.636895 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:49.648093 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.648554 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:49.803603 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.155s	user 0.103s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":429,"lbm_read_time_us":11483,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26005,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2000}
I20260812 06:19:49.804201 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=10.126437
I20260812 06:19:49.836678 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.032s	user 0.016s	sys 0.013s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13183,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.837421 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:49.956339 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.119s	user 0.086s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569749,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":392,"lbm_read_time_us":6624,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23501,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.957118 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=10.126437
I20260812 06:19:50.002934 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.046s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15297,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.003496 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:50.014317 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.015331 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushMRSOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:50.047492 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushMRSOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1529,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1608,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:50.048151 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling LogGCOp(e0b2119aa6c540a199263e2561d65445): free 120553376 bytes of WAL
I20260812 06:19:50.048396 31798 log_reader.cc:385] T e0b2119aa6c540a199263e2561d65445: removed 12 log segments from log reader
I20260812 06:19:50.048465 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000003 (ops 12-16)
I20260812 06:19:50.048542 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000004 (ops 17-21)
I20260812 06:19:50.048611 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000005 (ops 22-26)
I20260812 06:19:50.048655 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000006 (ops 27-30)
I20260812 06:19:50.048693 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000007 (ops 31-35)
I20260812 06:19:50.048731 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000008 (ops 36-40)
I20260812 06:19:50.048770 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000009 (ops 41-45)
I20260812 06:19:50.048808 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000010 (ops 46-50)
I20260812 06:19:50.048847 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000011 (ops 51-55)
I20260812 06:19:50.048887 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000012 (ops 56-60)
I20260812 06:19:50.048928 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000013 (ops 61-64)
I20260812 06:19:50.048966 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000014 (ops 65-69)
I20260812 06:19:50.077023 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: LogGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:50.077455 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=5.165500
I20260812 06:19:50.094197 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":6851279,"delete_count":0,"lbm_write_time_us":6892,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:19:50.094820 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling LogGCOp(e0b2119aa6c540a199263e2561d65445): free 12017932 bytes of WAL
I20260812 06:19:50.095068 31798 log_reader.cc:385] T e0b2119aa6c540a199263e2561d65445: removed 1 log segments from log reader
I20260812 06:19:50.095112 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000015 (ops 70-74)
I20260812 06:19:50.098426 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: LogGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.003s	user 0.001s	sys 0.000s Metrics: {}
I20260812 06:19:50.098954 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:50.111220 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.012s	user 0.002s	sys 0.004s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":1949,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:19:50.111682 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:50.296147 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.184s	user 0.126s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":852,"lbm_read_time_us":12528,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36453,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":70272,"thread_start_us":122,"threads_started":1,"update_count":3000}
I20260812 06:19:50.297025 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=14.095187
I20260812 06:19:50.347404 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.050s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23007,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.347865 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445): 483 bytes on disk
I20260812 06:19:50.348272 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445) 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:19:50.348699 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:50.360549 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.361044 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:50.514645 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.153s	user 0.113s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":9894,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30584,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:19:50.515604 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=12.110812
I20260812 06:19:50.553692 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.038s	user 0.029s	sys 0.008s Metrics: {"bytes_written":13866411,"delete_count":0,"lbm_write_time_us":16444,"lbm_writes_lt_1ms":341,"reinsert_count":0,"update_count":1690}
I20260812 06:19:50.554312 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=1.196750
I20260812 06:19:50.564956 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3334,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:19:50.565472 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:50.706902 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.141s	user 0.084s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672243,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":460,"lbm_read_time_us":9083,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23772,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":65536,"update_count":2000}
I20260812 06:19:50.707567 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=11.118625
I20260812 06:19:50.748826 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.041s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17888,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.749318 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:50.775744 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.026s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5171,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.776229 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:50.796505 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.020s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.797070 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:50.989969 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.193s	user 0.125s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":145,"lbm_read_time_us":14362,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30574,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":37248,"update_count":2500}
I20260812 06:19:50.990671 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=14.095187
I20260812 06:19:51.041761 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.051s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19934,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.042325 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:51.054044 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.054796 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:51.242875 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.188s	user 0.128s	sys 0.046s 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":677,"lbm_read_time_us":11086,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30404,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:51.243521 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=14.095187
I20260812 06:19:51.297840 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.054s	user 0.014s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20811,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.298584 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:51.310729 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.311240 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:51.472563 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.161s	user 0.132s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":356,"lbm_read_time_us":11284,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32943,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:19:51.473348 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=10.126437
I20260812 06:19:51.520471 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.047s	user 0.013s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18733,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.521050 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:51.545799 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.546311 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:51.558202 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.559080 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushMRSOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:51.592976 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushMRSOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1414,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1616,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:51.593685 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling LogGCOp(e0b2119aa6c540a199263e2561d65445): free 120553411 bytes of WAL
I20260812 06:19:51.593921 31798 log_reader.cc:385] T e0b2119aa6c540a199263e2561d65445: removed 12 log segments from log reader
I20260812 06:19:51.593967 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000016 (ops 75-79)
I20260812 06:19:51.593997 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000017 (ops 80-84)
I20260812 06:19:51.594058 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000018 (ops 85-89)
I20260812 06:19:51.594111 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000019 (ops 90-94)
I20260812 06:19:51.594153 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000020 (ops 95-98)
I20260812 06:19:51.594218 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000021 (ops 99-103)
I20260812 06:19:51.594259 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000022 (ops 104-108)
I20260812 06:19:51.594297 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000023 (ops 109-113)
I20260812 06:19:51.594341 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000024 (ops 114-118)
I20260812 06:19:51.594381 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000025 (ops 119-122)
I20260812 06:19:51.594422 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000026 (ops 123-127)
I20260812 06:19:51.594460 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000027 (ops 128-132)
I20260812 06:19:51.622011 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: LogGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:51.622450 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=4.173312
I20260812 06:19:51.654059 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.031s	user 0.012s	sys 0.015s Metrics: {"bytes_written":6153870,"delete_count":0,"lbm_write_time_us":7629,"lbm_writes_lt_1ms":153,"reinsert_count":0,"update_count":750}
I20260812 06:19:51.654738 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:51.661387 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":2082,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:19:51.661856 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:51.904966 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.243s	user 0.146s	sys 0.092s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979819,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":538,"lbm_read_time_us":16339,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41326,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:51.906250 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=15.087375
I20260812 06:19:51.965790 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.059s	user 0.045s	sys 0.011s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":27343,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:51.966336 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:51.984163 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.984634 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:51.994273 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.994810 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:52.189726 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.195s	user 0.134s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":713,"lbm_read_time_us":13573,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31826,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":3000}
I20260812 06:19:52.194864 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445): 482 bytes on disk
I20260812 06:19:52.195459 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:19:52.196204 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=15.087375
I20260812 06:19:52.257045 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.061s	user 0.032s	sys 0.026s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":26804,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:52.257675 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:52.284554 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.027s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5473,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.285033 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:52.295667 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.296136 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:52.491935 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.196s	user 0.115s	sys 0.079s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":850,"lbm_read_time_us":14150,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33681,"lbm_writes_lt_1ms":643,"mutex_wait_us":300,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":3000}
I20260812 06:19:52.492779 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=16.079562
I20260812 06:19:52.551251 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.058s	user 0.025s	sys 0.032s Metrics: {"bytes_written":18009847,"delete_count":0,"lbm_write_time_us":25950,"lbm_writes_lt_1ms":442,"reinsert_count":0,"update_count":2195}
I20260812 06:19:52.551932 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=1.196750
I20260812 06:19:52.572201 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.020s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2912934,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:19:52.572769 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:52.582799 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3589,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.583454 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:52.812525 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.229s	user 0.136s	sys 0.087s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877186,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":227,"lbm_read_time_us":14758,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39119,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":3000}
I20260812 06:19:52.813349 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=18.063937
I20260812 06:19:52.884974 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.071s	user 0.030s	sys 0.032s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31836,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.885537 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=2.188937
I20260812 06:19:52.897538 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.898319 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:53.108170 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.210s	user 0.149s	sys 0.056s 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":346,"lbm_read_time_us":13827,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33584,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:19:53.108860 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=16.079562
I20260812 06:19:53.186376 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.077s	user 0.039s	sys 0.023s Metrics: {"bytes_written":18091889,"delete_count":0,"lbm_write_time_us":31966,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":443,"reinsert_count":0,"update_count":2205}
I20260812 06:19:53.186988 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=5.165500
I20260812 06:19:53.204878 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.018s	user 0.002s	sys 0.013s Metrics: {"bytes_written":6523095,"delete_count":0,"lbm_write_time_us":6795,"lbm_writes_lt_1ms":162,"reinsert_count":0,"update_count":795}
I20260812 06:19:53.205484 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushMRSOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:53.238826 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushMRSOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1480,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1691,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:53.239675 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling LogGCOp(e0b2119aa6c540a199263e2561d65445): free 129320791 bytes of WAL
I20260812 06:19:53.239943 31798 log_reader.cc:385] T e0b2119aa6c540a199263e2561d65445: removed 13 log segments from log reader
I20260812 06:19:53.240010 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000028 (ops 133-137)
I20260812 06:19:53.240051 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000029 (ops 138-142)
I20260812 06:19:53.240084 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000030 (ops 143-147)
I20260812 06:19:53.240125 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000031 (ops 148-152)
I20260812 06:19:53.240162 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000032 (ops 153-157)
I20260812 06:19:53.240201 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000033 (ops 158-162)
I20260812 06:19:53.240240 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000034 (ops 163-167)
I20260812 06:19:53.240278 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000035 (ops 168-172)
I20260812 06:19:53.240316 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000036 (ops 173-176)
I20260812 06:19:53.240355 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000037 (ops 177-181)
I20260812 06:19:53.240392 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000038 (ops 182-186)
I20260812 06:19:53.240430 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000039 (ops 187-190)
I20260812 06:19:53.240468 31798 log.cc:1079] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Deleting log segment in path: /tmp/dist-test-taskNCD0PC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582015903-31455-0/minicluster-data/ts-0-root/wals/e0b2119aa6c540a199263e2561d65445/wal-000000040 (ops 191-195)
I20260812 06:19:53.270047 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: LogGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:53.270814 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=3.181125
I20260812 06:19:53.283833 31455 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.971s	user 1.856s	sys 0.154s
I20260812 06:19:53.288455 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":5251341,"delete_count":0,"lbm_write_time_us":7717,"lbm_writes_lt_1ms":131,"mutex_wait_us":80,"reinsert_count":0,"update_count":640}
I20260812 06:19:53.288898 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445): 493 bytes on disk
I20260812 06:19:53.289356 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: UndoDeltaBlockGCOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.289876 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445): perf score=1.196750
I20260812 06:19:53.297923 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: FlushDeltaMemStoresOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":2927,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:19:53.298377 31871 maintenance_manager.cc:419] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: Scheduling MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445): perf score=1.000000
I20260812 06:19:53.362746 31455 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.003s	sys 0.000s
I20260812 06:19:53.363299 31455 tablet_server.cc:179] TabletServer@127.30.183.193:0 shutting down...
I20260812 06:19:53.479900 31798 maintenance_manager.cc:643] P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: MajorDeltaCompactionOp(e0b2119aa6c540a199263e2561d65445) complete. Timing: real 0.181s	user 0.136s	sys 0.045s Metrics: {"cfile_cache_hit":297,"cfile_cache_hit_bytes":12106361,"cfile_cache_miss":537,"cfile_cache_miss_bytes":24975779,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":672,"lbm_read_time_us":10975,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36711,"lbm_writes_lt_1ms":843,"mutex_wait_us":21,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":20096,"thread_start_us":88,"threads_started":1,"update_count":4000}
I20260812 06:19:53.480759 31455 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:53.481165 31455 tablet_replica.cc:333] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a: stopping tablet replica
I20260812 06:19:53.481328 31455 raft_consensus.cc:2243] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.481559 31455 raft_consensus.cc:2272] T e0b2119aa6c540a199263e2561d65445 P f29ee03d8f8c4dcd80cbaf4c02ab5b0a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.496796 31455 tablet_server.cc:196] TabletServer@127.30.183.193:0 shutdown complete.
I20260812 06:19:53.554116 31455 master.cc:562] Master@127.30.183.254:42887 shutting down...
I20260812 06:19:53.557910 31455 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.558094 31455 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.558147 31455 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1d18470217e24191b0e6fe70ea3c0ab4: stopping tablet replica
I20260812 06:19:53.570796 31455 master.cc:584] Master@127.30.183.254:42887 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5547 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11633 ms total)

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