[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:30.126204 31305 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.146.126:43343
I20260812 06:17:30.127768 31305 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:30.128726 31305 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:30.136921 31313 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:30.136938 31314 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:30.137367 31316 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:30.137501 31305 server_base.cc:1061] running on GCE node
I20260812 06:17:30.138115 31305 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:30.138252 31305 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:30.138331 31305 hybrid_clock.cc:648] HybridClock initialized: now 1786515450138327 us; error 0 us; skew 500 ppm
I20260812 06:17:30.140354 31305 webserver.cc:533] Webserver started at http://127.30.146.126:46461/ using document root <none> and password file <none>
I20260812 06:17:30.141007 31305 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:30.141100 31305 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:30.141386 31305 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:30.143342 31305 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/master-0-root/instance:
uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-drl0"
I20260812 06:17:30.148123 31305 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.001s
I20260812 06:17:30.150910 31322 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.152189 31305 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:17:30.152345 31305 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/master-0-root
uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-drl0"
I20260812 06:17:30.152474 31305 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:30.191811 31305 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:30.192595 31305 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:30.192806 31305 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:30.201478 31305 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.126:43343
I20260812 06:17:30.201550 31402 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.126:43343 every 8 connection(s)
I20260812 06:17:30.204056 31403 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:30.209671 31403 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5: Bootstrap starting.
I20260812 06:17:30.212172 31403 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:30.213078 31403 log.cc:826] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:30.214905 31403 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5: No bootstrap required, opened a new log
I20260812 06:17:30.217723 31403 raft_consensus.cc:359] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5" member_type: VOTER }
I20260812 06:17:30.217892 31403 raft_consensus.cc:385] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:30.217933 31403 raft_consensus.cc:740] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ecb56bf58dcb4ea9ad1a041cd54473f5, State: Initialized, Role: FOLLOWER
I20260812 06:17:30.218633 31403 consensus_queue.cc:260] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [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: "ecb56bf58dcb4ea9ad1a041cd54473f5" member_type: VOTER }
I20260812 06:17:30.218780 31403 raft_consensus.cc:399] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:30.218873 31403 raft_consensus.cc:493] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:30.219064 31403 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:30.219866 31403 raft_consensus.cc:515] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5" member_type: VOTER }
I20260812 06:17:30.220327 31403 leader_election.cc:304] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [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: ecb56bf58dcb4ea9ad1a041cd54473f5; no voters: 
I20260812 06:17:30.220691 31403 leader_election.cc:290] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:30.220883 31406 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:30.221176 31406 raft_consensus.cc:697] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 1 LEADER]: Becoming Leader. State: Replica: ecb56bf58dcb4ea9ad1a041cd54473f5, State: Running, Role: LEADER
I20260812 06:17:30.221593 31406 consensus_queue.cc:237] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [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: "ecb56bf58dcb4ea9ad1a041cd54473f5" member_type: VOTER }
I20260812 06:17:30.221751 31403 sys_catalog.cc:565] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:30.224100 31410 sys_catalog.cc:455] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ecb56bf58dcb4ea9ad1a041cd54473f5. Latest consensus state: current_term: 1 leader_uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5" member_type: VOTER } }
I20260812 06:17:30.224128 31409 sys_catalog.cc:455] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecb56bf58dcb4ea9ad1a041cd54473f5" member_type: VOTER } }
I20260812 06:17:30.224217 31410 sys_catalog.cc:458] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:30.224373 31305 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:30.224225 31409 sys_catalog.cc:458] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [sys.catalog]: This master's current role is: LEADER
W20260812 06:17:30.226457 31426 catalog_manager.cc:1594] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:30.226536 31426 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:30.226589 31428 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:30.227480 31428 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:30.233275 31428 catalog_manager.cc:1383] Generated new cluster ID: 17ec2ef910bd4b7585684941872afd2c
I20260812 06:17:30.233384 31428 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:30.264456 31428 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:30.265408 31428 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:30.271319 31428 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5: Generated new TSK 0
I20260812 06:17:30.271955 31428 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:30.289649 31305 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:30.292801 31437 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:30.292965 31441 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:30.292965 31435 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:30.293474 31305 server_base.cc:1061] running on GCE node
I20260812 06:17:30.293694 31305 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:30.293743 31305 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:30.293761 31305 hybrid_clock.cc:648] HybridClock initialized: now 1786515450293760 us; error 0 us; skew 500 ppm
I20260812 06:17:30.294854 31305 webserver.cc:533] Webserver started at http://127.30.146.65:34583/ using document root <none> and password file <none>
I20260812 06:17:30.295080 31305 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:30.295156 31305 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:30.295248 31305 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:30.295697 31305 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/instance:
uuid: "704df164c4c24ea0874d46aeba1b2e8b"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-drl0"
I20260812 06:17:30.297286 31305 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:30.298313 31447 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.298571 31305 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:30.298643 31305 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root
uuid: "704df164c4c24ea0874d46aeba1b2e8b"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-drl0"
I20260812 06:17:30.298738 31305 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:30.308001 31305 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:30.308418 31305 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:30.308915 31305 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:30.309800 31305 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:30.309856 31305 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.309924 31305 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:30.309966 31305 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.317612 31305 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.65:46225
I20260812 06:17:30.317646 31545 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.65:46225 every 8 connection(s)
I20260812 06:17:30.329036 31546 heartbeater.cc:344] Connected to a master server at 127.30.146.126:43343
I20260812 06:17:30.329324 31546 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:30.329766 31546 heartbeater.cc:507] Master 127.30.146.126:43343 requested a full tablet report, sending...
I20260812 06:17:30.331321 31347 ts_manager.cc:194] Registered new tserver with Master: 704df164c4c24ea0874d46aeba1b2e8b (127.30.146.65:46225)
I20260812 06:17:30.331804 31305 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013522606s
I20260812 06:17:30.332531 31347 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60790
I20260812 06:17:30.343986 31347 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60792:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:30.360747 31486 tablet_service.cc:1511] Processing CreateTablet for tablet 3d871fcbec3a417495ecb98054227384 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1b23fc307ea44cf59b27986f1ae4cf7e]), partition=
I20260812 06:17:30.361507 31486 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3d871fcbec3a417495ecb98054227384. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:30.364498 31565 tablet_bootstrap.cc:492] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Bootstrap starting.
I20260812 06:17:30.366272 31565 tablet_bootstrap.cc:654] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:30.367835 31565 tablet_bootstrap.cc:492] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: No bootstrap required, opened a new log
I20260812 06:17:30.368022 31565 ts_tablet_manager.cc:1403] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:30.368764 31565 raft_consensus.cc:359] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "704df164c4c24ea0874d46aeba1b2e8b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 46225 } }
I20260812 06:17:30.368893 31565 raft_consensus.cc:385] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:30.368950 31565 raft_consensus.cc:740] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 704df164c4c24ea0874d46aeba1b2e8b, State: Initialized, Role: FOLLOWER
I20260812 06:17:30.369262 31565 consensus_queue.cc:260] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [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: "704df164c4c24ea0874d46aeba1b2e8b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 46225 } }
I20260812 06:17:30.369431 31565 raft_consensus.cc:399] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:30.369495 31565 raft_consensus.cc:493] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:30.369562 31565 raft_consensus.cc:3060] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:30.370568 31565 raft_consensus.cc:515] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "704df164c4c24ea0874d46aeba1b2e8b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 46225 } }
I20260812 06:17:30.370743 31565 leader_election.cc:304] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [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: 704df164c4c24ea0874d46aeba1b2e8b; no voters: 
I20260812 06:17:30.371029 31565 leader_election.cc:290] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:30.371126 31568 raft_consensus.cc:2804] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:30.371340 31568 raft_consensus.cc:697] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 1 LEADER]: Becoming Leader. State: Replica: 704df164c4c24ea0874d46aeba1b2e8b, State: Running, Role: LEADER
I20260812 06:17:30.371434 31565 ts_tablet_manager.cc:1434] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:30.371557 31568 consensus_queue.cc:237] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [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: "704df164c4c24ea0874d46aeba1b2e8b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 46225 } }
I20260812 06:17:30.371755 31546 heartbeater.cc:499] Master 127.30.146.126:43343 was elected leader, sending a full tablet report...
I20260812 06:17:30.374996 31347 catalog_manager.cc:5719] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b reported cstate change: term changed from 0 to 1, leader changed from <none> to 704df164c4c24ea0874d46aeba1b2e8b (127.30.146.65). New cstate: current_term: 1 leader_uuid: "704df164c4c24ea0874d46aeba1b2e8b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "704df164c4c24ea0874d46aeba1b2e8b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 46225 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:30.455808 31305 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.073s	user 0.023s	sys 0.012s
I20260812 06:17:30.568959 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushMRSOp(3d871fcbec3a417495ecb98054227384): perf score=14.094003
I20260812 06:17:30.734870 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushMRSOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.165s	user 0.125s	sys 0.036s Metrics: {"bytes_written":8861466,"cfile_init":1,"compiler_manager_pool.queue_time_us":227,"delete_count":0,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":766,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44052,"lbm_writes_lt_1ms":573,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":162048,"thread_start_us":157,"threads_started":1,"update_count":1080}
I20260812 06:17:30.736168 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling LogGCOp(3d871fcbec3a417495ecb98054227384): free 20290830 bytes of WAL
I20260812 06:17:30.736508 31455 log_reader.cc:385] T 3d871fcbec3a417495ecb98054227384: removed 2 log segments from log reader
I20260812 06:17:30.736600 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000001 (ops 1-6)
I20260812 06:17:30.736677 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000002 (ops 7-10)
I20260812 06:17:30.743027 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: LogGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.007s	user 0.000s	sys 0.007s Metrics: {}
I20260812 06:17:30.743438 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:30.757818 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3856511,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:17:30.758671 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:30.773082 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.014s	user 0.012s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5615,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.773536 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:30.939543 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.166s	user 0.108s	sys 0.057s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631417,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":72,"lbm_read_time_us":12825,"lbm_reads_lt_1ms":473,"lbm_write_time_us":35792,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":220,"threads_started":5,"update_count":2000}
I20260812 06:17:30.940083 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=10.126437
I20260812 06:17:30.994346 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.054s	user 0.021s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23194,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:17:30.994916 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:31.008314 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.008795 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384): 12308960 bytes on disk
I20260812 06:17:31.009449 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:17:31.009895 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:31.160755 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.151s	user 0.115s	sys 0.035s 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":396,"lbm_read_time_us":11053,"lbm_reads_lt_1ms":472,"lbm_write_time_us":37327,"lbm_writes_lt_1ms":443,"mutex_wait_us":357,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:31.161284 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=10.126437
I20260812 06:17:31.219028 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.058s	user 0.032s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21737,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.219645 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:31.237527 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.238094 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:31.400175 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.162s	user 0.094s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1451,"lbm_read_time_us":12895,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28577,"lbm_writes_lt_1ms":443,"mutex_wait_us":455,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:17:31.401113 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=10.126437
I20260812 06:17:31.452991 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.052s	user 0.028s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22874,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.453496 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:31.467150 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.467670 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:31.611593 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.144s	user 0.112s	sys 0.032s 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":764,"lbm_read_time_us":11087,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31581,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:17:31.612249 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=10.126437
I20260812 06:17:31.661372 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.049s	user 0.022s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":25600,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.661943 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:31.679229 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6892,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.679737 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:31.818413 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.139s	user 0.101s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":717,"lbm_read_time_us":9515,"lbm_reads_lt_1ms":468,"lbm_write_time_us":30509,"lbm_writes_lt_1ms":443,"mutex_wait_us":80,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.819164 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=10.126437
I20260812 06:17:31.864760 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22321,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.865437 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:31.878369 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.879112 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:32.047469 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.168s	user 0.124s	sys 0.033s 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":231,"lbm_read_time_us":10333,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34190,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:32.048173 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=11.118625
I20260812 06:17:32.093806 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.045s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16132,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:32.094511 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:32.123241 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.029s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5373,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.123705 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:32.137486 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5526,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.138159 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushMRSOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:32.179939 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushMRSOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.042s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1256,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1573,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:32.180922 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling LogGCOp(3d871fcbec3a417495ecb98054227384): free 108535461 bytes of WAL
I20260812 06:17:32.181239 31455 log_reader.cc:385] T 3d871fcbec3a417495ecb98054227384: removed 11 log segments from log reader
I20260812 06:17:32.181316 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000003 (ops 11-15)
I20260812 06:17:32.181373 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000004 (ops 16-20)
I20260812 06:17:32.181434 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000005 (ops 21-24)
I20260812 06:17:32.181474 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000006 (ops 25-29)
I20260812 06:17:32.181512 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000007 (ops 30-34)
I20260812 06:17:32.181547 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000008 (ops 35-39)
I20260812 06:17:32.181586 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000009 (ops 40-44)
I20260812 06:17:32.181627 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000010 (ops 45-49)
I20260812 06:17:32.181668 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000011 (ops 50-54)
I20260812 06:17:32.181710 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000012 (ops 55-58)
I20260812 06:17:32.181749 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000013 (ops 59-63)
I20260812 06:17:32.209352 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: LogGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:32.209899 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384): 462 bytes on disk
I20260812 06:17:32.210497 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.211166 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=3.181125
I20260812 06:17:32.226044 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.015s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4663,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:32.226446 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:32.237913 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4748,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.238350 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:32.487258 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.249s	user 0.156s	sys 0.088s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938886,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1609,"lbm_read_time_us":18059,"lbm_reads_lt_1ms":775,"lbm_write_time_us":45147,"lbm_writes_lt_1ms":743,"mutex_wait_us":1152,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:17:32.488348 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=15.087375
I20260812 06:17:32.550539 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.062s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":24934,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:32.551168 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:32.568934 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7453,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.569380 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:32.581967 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4816,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.582693 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:32.772274 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.189s	user 0.157s	sys 0.031s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836241,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":394,"lbm_read_time_us":15157,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39738,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:17:32.773073 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:32.827360 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.054s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23753,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.827941 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:32.842382 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.843428 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:33.024433 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.181s	user 0.129s	sys 0.044s 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":902,"lbm_read_time_us":11131,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35172,"lbm_writes_lt_1ms":543,"mutex_wait_us":322,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:17:33.025157 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:33.081480 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.056s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22481,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.082149 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:33.263296 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.181s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1235,"lbm_read_time_us":11743,"lbm_reads_lt_1ms":463,"lbm_write_time_us":30830,"lbm_writes_lt_1ms":443,"mutex_wait_us":350,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:33.263964 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:33.321447 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.057s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21985,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.321949 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:33.348932 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.027s	user 0.014s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.349457 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:33.538290 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.189s	user 0.128s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":13362,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29577,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:33.538990 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:33.594409 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.055s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24157,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.595008 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:33.613883 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.019s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.614552 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:33.792038 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.177s	user 0.131s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":759,"lbm_read_time_us":12326,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34225,"lbm_writes_lt_1ms":543,"mutex_wait_us":200,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:17:33.792680 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=11.118625
I20260812 06:17:33.828754 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.036s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14846,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:33.829465 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:33.847005 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6828,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.847831 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushMRSOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:33.887801 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushMRSOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.040s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":124,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1271,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1971,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:33.888733 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384): 493 bytes on disk
I20260812 06:17:33.889128 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384) 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:17:33.889600 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=3.181125
I20260812 06:17:33.900767 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4402,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:33.901175 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling LogGCOp(3d871fcbec3a417495ecb98054227384): free 133024364 bytes of WAL
I20260812 06:17:33.901401 31455 log_reader.cc:385] T 3d871fcbec3a417495ecb98054227384: removed 13 log segments from log reader
I20260812 06:17:33.901443 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000014 (ops 64-68)
I20260812 06:17:33.901473 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000015 (ops 69-72)
I20260812 06:17:33.901539 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000016 (ops 73-77)
I20260812 06:17:33.901579 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000017 (ops 78-82)
I20260812 06:17:33.901618 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000018 (ops 83-87)
I20260812 06:17:33.901655 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000019 (ops 88-92)
I20260812 06:17:33.901695 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000020 (ops 93-97)
I20260812 06:17:33.901732 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000021 (ops 98-102)
I20260812 06:17:33.901770 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000022 (ops 103-107)
I20260812 06:17:33.901808 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000023 (ops 108-112)
I20260812 06:17:33.901847 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000024 (ops 113-117)
I20260812 06:17:33.901887 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000025 (ops 118-122)
I20260812 06:17:33.901925 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000026 (ops 123-127)
I20260812 06:17:33.932641 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: LogGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:33.933190 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:33.955964 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.022s	user 0.015s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6618,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.956506 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling LogGCOp(3d871fcbec3a417495ecb98054227384): free 12017949 bytes of WAL
I20260812 06:17:33.956785 31455 log_reader.cc:385] T 3d871fcbec3a417495ecb98054227384: removed 1 log segments from log reader
I20260812 06:17:33.956861 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000027 (ops 128-132)
I20260812 06:17:33.960472 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: LogGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:33.960803 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:33.971848 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.972219 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:34.208758 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.236s	user 0.161s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938887,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":842,"lbm_read_time_us":16455,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37757,"lbm_writes_lt_1ms":743,"mutex_wait_us":63,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:17:34.210081 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=17.071750
I20260812 06:17:34.273872 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.064s	user 0.032s	sys 0.023s Metrics: {"bytes_written":18994432,"delete_count":0,"lbm_write_time_us":26768,"lbm_writes_lt_1ms":466,"reinsert_count":0,"update_count":2315}
I20260812 06:17:34.274444 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:34.284983 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.010s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2174487,"delete_count":0,"lbm_write_time_us":2452,"lbm_writes_lt_1ms":56,"mutex_wait_us":180,"reinsert_count":0,"update_count":265}
I20260812 06:17:34.285501 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:34.296440 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:17:34.297127 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:34.513212 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.216s	user 0.124s	sys 0.092s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":329,"lbm_read_time_us":17572,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35588,"lbm_writes_lt_1ms":643,"mutex_wait_us":77,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":48640,"update_count":3000}
I20260812 06:17:34.514195 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:34.563187 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.048s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21498,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.564257 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:34.577600 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.578150 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:34.768633 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.190s	user 0.113s	sys 0.071s 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":273,"lbm_read_time_us":14875,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30492,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:34.769299 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:34.843649 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.074s	user 0.042s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":27388,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.844177 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:34.856236 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.857034 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:35.049088 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.192s	user 0.125s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":556,"lbm_read_time_us":13418,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32326,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:35.049778 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:35.115236 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.065s	user 0.026s	sys 0.038s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27851,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.115741 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:35.129812 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.130360 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:35.312378 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.182s	user 0.120s	sys 0.055s 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":580,"lbm_read_time_us":14173,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28495,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":2500}
I20260812 06:17:35.312951 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=14.095187
I20260812 06:17:35.374372 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.061s	user 0.022s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24083,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.375149 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=2.188937
I20260812 06:17:35.386085 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.386530 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushMRSOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:35.422047 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushMRSOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.035s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1235,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1612,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:35.423028 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384): 447 bytes on disk
I20260812 06:17:35.423528 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: UndoDeltaBlockGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.424149 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:35.597116 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.173s	user 0.104s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":547,"lbm_read_time_us":10840,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28432,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:17:35.597920 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling LogGCOp(3d871fcbec3a417495ecb98054227384): free 108535648 bytes of WAL
I20260812 06:17:35.598274 31455 log_reader.cc:385] T 3d871fcbec3a417495ecb98054227384: removed 11 log segments from log reader
I20260812 06:17:35.598353 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000028 (ops 133-137)
I20260812 06:17:35.598445 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000029 (ops 138-142)
I20260812 06:17:35.598489 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000030 (ops 143-146)
I20260812 06:17:35.598551 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000031 (ops 147-151)
I20260812 06:17:35.598593 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000032 (ops 152-156)
I20260812 06:17:35.598636 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000033 (ops 157-161)
I20260812 06:17:35.598678 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000034 (ops 162-166)
I20260812 06:17:35.598723 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000035 (ops 167-171)
I20260812 06:17:35.598778 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000036 (ops 172-176)
I20260812 06:17:35.598821 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000037 (ops 177-180)
I20260812 06:17:35.598865 31455 log.cc:1079] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/3d871fcbec3a417495ecb98054227384/wal-000000038 (ops 181-185)
I20260812 06:17:35.627429 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: LogGCOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.029s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:35.628298 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=17.071750
I20260812 06:17:35.711017 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.082s	user 0.036s	sys 0.040s Metrics: {"bytes_written":19117496,"delete_count":0,"lbm_write_time_us":30908,"lbm_writes_lt_1ms":469,"reinsert_count":0,"update_count":2330}
I20260812 06:17:35.711615 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384): perf score=4.173312
I20260812 06:17:35.726466 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: FlushDeltaMemStoresOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":5497489,"delete_count":0,"lbm_write_time_us":6183,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:17:35.727161 31547 maintenance_manager.cc:419] P 704df164c4c24ea0874d46aeba1b2e8b: Scheduling MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384): perf score=1.000000
I20260812 06:17:35.829166 31305 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.373s	user 2.001s	sys 0.155s
I20260812 06:17:35.924252 31305 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.004s	sys 0.000s
I20260812 06:17:35.925199 31305 tablet_server.cc:179] TabletServer@127.30.146.65:0 shutting down...
I20260812 06:17:35.936568 31455 maintenance_manager.cc:643] P 704df164c4c24ea0874d46aeba1b2e8b: MajorDeltaCompactionOp(3d871fcbec3a417495ecb98054227384) complete. Timing: real 0.209s	user 0.132s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836142,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":454,"lbm_read_time_us":17091,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36120,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:35.937927 31305 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:35.938462 31305 tablet_replica.cc:333] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b: stopping tablet replica
I20260812 06:17:35.938726 31305 raft_consensus.cc:2243] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.939043 31305 raft_consensus.cc:2272] T 3d871fcbec3a417495ecb98054227384 P 704df164c4c24ea0874d46aeba1b2e8b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.959120 31305 tablet_server.cc:196] TabletServer@127.30.146.65:0 shutdown complete.
I20260812 06:17:35.991542 31305 master.cc:562] Master@127.30.146.126:43343 shutting down...
I20260812 06:17:35.996459 31305 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.996621 31305 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.996727 31305 tablet_replica.cc:333] T 00000000000000000000000000000000 P ecb56bf58dcb4ea9ad1a041cd54473f5: stopping tablet replica
I20260812 06:17:36.009481 31305 master.cc:584] Master@127.30.146.126:43343 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5985 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:36.123378 31305 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.146.126:38947
I20260812 06:17:36.123873 31305 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:36.126917 31597 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:36.126983 31601 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:36.127200 31598 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:36.127247 31305 server_base.cc:1061] running on GCE node
I20260812 06:17:36.127498 31305 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:36.127539 31305 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:36.127555 31305 hybrid_clock.cc:648] HybridClock initialized: now 1786515456127555 us; error 0 us; skew 500 ppm
I20260812 06:17:36.128597 31305 webserver.cc:533] Webserver started at http://127.30.146.126:36377/ using document root <none> and password file <none>
I20260812 06:17:36.128804 31305 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:36.128880 31305 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:36.128964 31305 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:36.129397 31305 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/master-0-root/instance:
uuid: "0d6afb323d7b4a94add27b046375646e"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-drl0"
I20260812 06:17:36.131093 31305 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:36.132512 31609 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:36.132977 31305 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:36.133217 31305 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/master-0-root
uuid: "0d6afb323d7b4a94add27b046375646e"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-drl0"
I20260812 06:17:36.133355 31305 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:36.153983 31305 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:36.154420 31305 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:36.159770 31305 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.126:38947
I20260812 06:17:36.165846 31682 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.126:38947 every 8 connection(s)
I20260812 06:17:36.166330 31683 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:36.168188 31683 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e: Bootstrap starting.
I20260812 06:17:36.168941 31683 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:36.169977 31683 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e: No bootstrap required, opened a new log
I20260812 06:17:36.170331 31683 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d6afb323d7b4a94add27b046375646e" member_type: VOTER }
I20260812 06:17:36.170428 31683 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:36.170451 31683 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0d6afb323d7b4a94add27b046375646e, State: Initialized, Role: FOLLOWER
I20260812 06:17:36.170570 31683 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [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: "0d6afb323d7b4a94add27b046375646e" member_type: VOTER }
I20260812 06:17:36.170632 31683 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:36.170655 31683 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:36.170696 31683 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:36.171418 31683 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d6afb323d7b4a94add27b046375646e" member_type: VOTER }
I20260812 06:17:36.171530 31683 leader_election.cc:304] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [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: 0d6afb323d7b4a94add27b046375646e; no voters: 
I20260812 06:17:36.171774 31683 leader_election.cc:290] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:36.171967 31688 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:36.172214 31688 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 1 LEADER]: Becoming Leader. State: Replica: 0d6afb323d7b4a94add27b046375646e, State: Running, Role: LEADER
I20260812 06:17:36.172317 31683 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:36.172349 31688 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [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: "0d6afb323d7b4a94add27b046375646e" member_type: VOTER }
I20260812 06:17:36.172931 31690 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0d6afb323d7b4a94add27b046375646e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d6afb323d7b4a94add27b046375646e" member_type: VOTER } }
I20260812 06:17:36.172983 31691 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0d6afb323d7b4a94add27b046375646e. Latest consensus state: current_term: 1 leader_uuid: "0d6afb323d7b4a94add27b046375646e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d6afb323d7b4a94add27b046375646e" member_type: VOTER } }
I20260812 06:17:36.173106 31690 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:36.173127 31691 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:36.173596 31698 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:36.174484 31698 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:36.174728 31305 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:36.176819 31698 catalog_manager.cc:1383] Generated new cluster ID: 9ca15905a1be41f3b5fcea8568c4c873
I20260812 06:17:36.176873 31698 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:36.185823 31698 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:36.186298 31698 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:36.194465 31698 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e: Generated new TSK 0
I20260812 06:17:36.194622 31698 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:36.207640 31305 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:36.210078 31720 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:36.210121 31717 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:36.210167 31718 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:36.210353 31305 server_base.cc:1061] running on GCE node
I20260812 06:17:36.210507 31305 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:36.210566 31305 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:36.210592 31305 hybrid_clock.cc:648] HybridClock initialized: now 1786515456210592 us; error 0 us; skew 500 ppm
I20260812 06:17:36.211517 31305 webserver.cc:533] Webserver started at http://127.30.146.65:33129/ using document root <none> and password file <none>
I20260812 06:17:36.211704 31305 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:36.211774 31305 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:36.211863 31305 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:36.212268 31305 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/instance:
uuid: "67e1dc411e534f6ba04bc05f2b14fa4b"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-drl0"
I20260812 06:17:36.213943 31305 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:36.215406 31727 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:36.215817 31305 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:36.215938 31305 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root
uuid: "67e1dc411e534f6ba04bc05f2b14fa4b"
format_stamp: "Formatted at 2026-08-12 06:17:36 on dist-test-slave-drl0"
I20260812 06:17:36.216037 31305 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:36.229893 31305 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:36.230285 31305 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:36.230589 31305 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:36.231159 31305 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:36.231220 31305 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:36.231276 31305 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:36.231324 31305 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:36.237107 31305 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.65:40753
I20260812 06:17:36.237907 31821 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.65:40753 every 8 connection(s)
I20260812 06:17:36.246469 31822 heartbeater.cc:344] Connected to a master server at 127.30.146.126:38947
I20260812 06:17:36.246575 31822 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:36.246759 31822 heartbeater.cc:507] Master 127.30.146.126:38947 requested a full tablet report, sending...
I20260812 06:17:36.247495 31634 ts_manager.cc:194] Registered new tserver with Master: 67e1dc411e534f6ba04bc05f2b14fa4b (127.30.146.65:40753)
I20260812 06:17:36.248189 31634 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53110
I20260812 06:17:36.248317 31305 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010303661s
I20260812 06:17:36.256206 31634 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53116:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:36.267241 31765 tablet_service.cc:1511] Processing CreateTablet for tablet ec172c83b7f24fb2bf05bb6ca23d8ecd (DEFAULT_TABLE table=heavy-update-compaction-test [id=1fba42ead4974c928304e1ffb7c11bf1]), partition=
I20260812 06:17:36.267549 31765 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ec172c83b7f24fb2bf05bb6ca23d8ecd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:36.269656 31837 tablet_bootstrap.cc:492] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Bootstrap starting.
I20260812 06:17:36.270821 31837 tablet_bootstrap.cc:654] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:36.272045 31837 tablet_bootstrap.cc:492] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: No bootstrap required, opened a new log
I20260812 06:17:36.272126 31837 ts_tablet_manager.cc:1403] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:36.272503 31837 raft_consensus.cc:359] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67e1dc411e534f6ba04bc05f2b14fa4b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 40753 } }
I20260812 06:17:36.272596 31837 raft_consensus.cc:385] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:36.272619 31837 raft_consensus.cc:740] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 67e1dc411e534f6ba04bc05f2b14fa4b, State: Initialized, Role: FOLLOWER
I20260812 06:17:36.272799 31837 consensus_queue.cc:260] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [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: "67e1dc411e534f6ba04bc05f2b14fa4b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 40753 } }
I20260812 06:17:36.272912 31837 raft_consensus.cc:399] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:36.272956 31837 raft_consensus.cc:493] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:36.273000 31837 raft_consensus.cc:3060] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:36.274060 31837 raft_consensus.cc:515] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67e1dc411e534f6ba04bc05f2b14fa4b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 40753 } }
I20260812 06:17:36.274187 31837 leader_election.cc:304] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [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: 67e1dc411e534f6ba04bc05f2b14fa4b; no voters: 
I20260812 06:17:36.274430 31837 leader_election.cc:290] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:36.274609 31840 raft_consensus.cc:2804] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:36.274876 31837 ts_tablet_manager.cc:1434] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:36.274873 31822 heartbeater.cc:499] Master 127.30.146.126:38947 was elected leader, sending a full tablet report...
I20260812 06:17:36.275051 31840 raft_consensus.cc:697] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 1 LEADER]: Becoming Leader. State: Replica: 67e1dc411e534f6ba04bc05f2b14fa4b, State: Running, Role: LEADER
I20260812 06:17:36.275194 31840 consensus_queue.cc:237] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [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: "67e1dc411e534f6ba04bc05f2b14fa4b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 40753 } }
I20260812 06:17:36.276422 31634 catalog_manager.cc:5719] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b reported cstate change: term changed from 0 to 1, leader changed from <none> to 67e1dc411e534f6ba04bc05f2b14fa4b (127.30.146.65). New cstate: current_term: 1 leader_uuid: "67e1dc411e534f6ba04bc05f2b14fa4b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67e1dc411e534f6ba04bc05f2b14fa4b" member_type: VOTER last_known_addr { host: "127.30.146.65" port: 40753 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:36.342814 31305 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.020s	sys 0.004s
I20260812 06:17:36.488543 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=15.086190
I20260812 06:17:36.653452 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.165s	user 0.121s	sys 0.040s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":815,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39491,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:17:36.654186 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): free 20743880 bytes of WAL
I20260812 06:17:36.654429 31733 log_reader.cc:385] T ec172c83b7f24fb2bf05bb6ca23d8ecd: removed 2 log segments from log reader
I20260812 06:17:36.654501 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000001 (ops 1-6)
I20260812 06:17:36.654560 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000002 (ops 7-11)
I20260812 06:17:36.659166 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:36.659461 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): 12719216 bytes on disk
I20260812 06:17:36.659880 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.660256 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:36.674968 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.015s	user 0.003s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.675860 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:36.847666 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.171s	user 0.124s	sys 0.047s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":14364,"lbm_reads_lt_1ms":454,"lbm_write_time_us":26957,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":361,"threads_started":5,"update_count":1950}
I20260812 06:17:36.848290 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:36.886183 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.038s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16574,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.887040 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:36.905098 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.905548 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:37.050400 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.145s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":12669,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29096,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2000}
I20260812 06:17:37.051172 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:37.094216 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.043s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17164,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.094811 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:37.106274 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.106959 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:37.250653 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.144s	user 0.118s	sys 0.025s 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":1080,"lbm_read_time_us":9833,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28256,"lbm_writes_lt_1ms":443,"mutex_wait_us":438,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:17:37.251451 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:37.301463 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.050s	user 0.035s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18582,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.302119 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:37.317966 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.318504 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:37.459226 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.140s	user 0.097s	sys 0.043s 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":173,"lbm_read_time_us":10145,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26470,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:17:37.459950 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:37.517735 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.058s	user 0.019s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18689,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.518325 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:37.529915 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.530350 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:37.687057 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.157s	user 0.107s	sys 0.049s 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":1008,"lbm_read_time_us":12032,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24433,"lbm_writes_lt_1ms":443,"mutex_wait_us":342,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:17:37.687886 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:37.733506 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.045s	user 0.013s	sys 0.026s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18027,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.733946 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:37.744591 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.745041 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:37.879630 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.134s	user 0.087s	sys 0.047s 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":268,"lbm_read_time_us":9886,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25663,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:17:37.880376 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:37.928507 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.048s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18056,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.929083 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:37.941835 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.942529 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:38.077579 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.135s	user 0.098s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1149,"lbm_read_time_us":10374,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26900,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:17:38.078325 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:38.126892 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.048s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17267,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:38.127566 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:38.141963 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.142700 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:38.178462 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":313,"dirs.run_wall_time_us":1314,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2815,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:38.179400 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): free 120553380 bytes of WAL
I20260812 06:17:38.179800 31733 log_reader.cc:385] T ec172c83b7f24fb2bf05bb6ca23d8ecd: removed 12 log segments from log reader
I20260812 06:17:38.179903 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000003 (ops 12-16)
I20260812 06:17:38.179952 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000004 (ops 17-21)
I20260812 06:17:38.179983 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000005 (ops 22-26)
I20260812 06:17:38.180011 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000006 (ops 27-30)
I20260812 06:17:38.180050 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000007 (ops 31-35)
I20260812 06:17:38.180079 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000008 (ops 36-40)
I20260812 06:17:38.180114 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000009 (ops 41-45)
I20260812 06:17:38.180152 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000010 (ops 46-50)
I20260812 06:17:38.180181 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000011 (ops 51-54)
I20260812 06:17:38.180215 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000012 (ops 55-59)
I20260812 06:17:38.180254 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000013 (ops 60-64)
I20260812 06:17:38.180291 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000014 (ops 65-69)
I20260812 06:17:38.208730 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.029s	user 0.003s	sys 0.024s Metrics: {"spinlock_wait_cycles":3456}
I20260812 06:17:38.209681 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=6.157687
I20260812 06:17:38.230959 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":7466642,"delete_count":0,"lbm_write_time_us":8369,"lbm_writes_lt_1ms":185,"reinsert_count":0,"update_count":910}
I20260812 06:17:38.231490 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): free 8767123 bytes of WAL
I20260812 06:17:38.231696 31733 log_reader.cc:385] T ec172c83b7f24fb2bf05bb6ca23d8ecd: removed 1 log segments from log reader
I20260812 06:17:38.231798 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000015 (ops 70-74)
I20260812 06:17:38.233621 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:38.233958 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): 493 bytes on disk
I20260812 06:17:38.234414 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.234928 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:38.243180 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":1148856,"delete_count":0,"lbm_write_time_us":2302,"lbm_writes_lt_1ms":31,"reinsert_count":0,"update_count":140}
I20260812 06:17:38.243535 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:38.466464 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.223s	user 0.144s	sys 0.073s Metrics: {"cfile_cache_miss":644,"cfile_cache_miss_bytes":29287514,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":894,"lbm_read_time_us":15287,"lbm_reads_lt_1ms":676,"lbm_write_time_us":38011,"lbm_writes_lt_1ms":653,"mutex_wait_us":107,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":101,"threads_started":1,"update_count":3050}
I20260812 06:17:38.467319 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=18.063937
I20260812 06:17:38.526031 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.058s	user 0.031s	sys 0.025s Metrics: {"bytes_written":20102073,"delete_count":0,"lbm_write_time_us":27958,"lbm_writes_lt_1ms":493,"reinsert_count":0,"update_count":2450}
I20260812 06:17:38.526567 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:38.541669 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.542174 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:38.743726 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.201s	user 0.149s	sys 0.052s Metrics: {"cfile_cache_miss":622,"cfile_cache_miss_bytes":28466860,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":910,"lbm_read_time_us":15277,"lbm_reads_lt_1ms":654,"lbm_write_time_us":39318,"lbm_writes_lt_1ms":633,"mutex_wait_us":1,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":28288,"update_count":2950}
I20260812 06:17:38.744362 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=15.087375
I20260812 06:17:38.801153 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.057s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":25672,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:38.801677 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:38.816023 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5512,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.816497 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:39.013835 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.197s	user 0.121s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":12110,"lbm_reads_lt_1ms":564,"lbm_write_time_us":36039,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:17:39.014523 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=14.095187
I20260812 06:17:39.072060 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.057s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23238,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.072675 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:39.240782 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.168s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":856,"lbm_read_time_us":12134,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29311,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2000}
I20260812 06:17:39.241470 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=14.095187
I20260812 06:17:39.290258 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.049s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.290830 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:39.305526 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5853,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.306358 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:39.530303 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.224s	user 0.145s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":12591,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33167,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2500}
I20260812 06:17:39.531286 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=14.095187
I20260812 06:17:39.588810 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.057s	user 0.047s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26077,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.589421 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:39.602689 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.603413 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:39.774745 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.171s	user 0.111s	sys 0.057s 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":1205,"lbm_read_time_us":10315,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35887,"lbm_writes_lt_1ms":543,"mutex_wait_us":318,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:39.775355 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=11.118625
I20260812 06:17:39.815529 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.040s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17601,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:39.816339 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:39.843784 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.027s	user 0.015s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6687,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.844280 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:39.855628 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.856144 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:39.895516 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.039s	user 0.035s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1142,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2376,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:39.896201 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): free 127961141 bytes of WAL
I20260812 06:17:39.896418 31733 log_reader.cc:385] T ec172c83b7f24fb2bf05bb6ca23d8ecd: removed 12 log segments from log reader
I20260812 06:17:39.896462 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000016 (ops 75-79)
I20260812 06:17:39.896490 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000017 (ops 80-84)
I20260812 06:17:39.896559 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000018 (ops 85-89)
I20260812 06:17:39.896600 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000019 (ops 90-94)
I20260812 06:17:39.896639 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000020 (ops 95-99)
I20260812 06:17:39.896696 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000021 (ops 100-104)
I20260812 06:17:39.896739 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000022 (ops 105-109)
I20260812 06:17:39.896780 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000023 (ops 110-114)
I20260812 06:17:39.896819 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000024 (ops 115-119)
I20260812 06:17:39.896858 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000025 (ops 120-124)
I20260812 06:17:39.896895 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000026 (ops 125-129)
I20260812 06:17:39.897347 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000027 (ops 130-134)
I20260812 06:17:39.930641 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:39.931177 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): 482 bytes on disk
I20260812 06:17:39.931810 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:39.932781 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=3.181125
I20260812 06:17:39.966169 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.033s	user 0.008s	sys 0.021s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":7844,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:17:39.967031 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.196750
I20260812 06:17:39.975955 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3237,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:17:39.976708 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:40.233388 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.256s	user 0.180s	sys 0.075s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":318,"lbm_read_time_us":17919,"lbm_reads_lt_1ms":775,"lbm_write_time_us":42489,"lbm_writes_lt_1ms":743,"mutex_wait_us":51,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":21120,"thread_start_us":125,"threads_started":1,"update_count":3500}
I20260812 06:17:40.234113 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=14.095187
I20260812 06:17:40.302030 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.068s	user 0.035s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29304,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.302624 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:40.314688 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.315369 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:40.532230 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.217s	user 0.121s	sys 0.091s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":15911,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35459,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:40.532999 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:40.586182 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.047s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17523,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.586830 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:40.729176 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.142s	user 0.103s	sys 0.034s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":364,"lbm_read_time_us":6774,"lbm_reads_lt_1ms":363,"lbm_write_time_us":28320,"lbm_writes_lt_1ms":343,"mutex_wait_us":25,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":1500}
I20260812 06:17:40.729898 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=7.149875
I20260812 06:17:40.755605 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.025s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11082,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:40.758882 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:40.776242 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6008,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:40.777052 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:40.909371 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.132s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":690,"lbm_read_time_us":8333,"lbm_reads_lt_1ms":372,"lbm_write_time_us":23953,"lbm_writes_lt_1ms":343,"mutex_wait_us":378,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":1500}
I20260812 06:17:40.909982 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:40.969969 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.060s	user 0.036s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18979,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.970507 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:40.982113 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.982654 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:41.135567 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.153s	user 0.097s	sys 0.055s 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":1048,"lbm_read_time_us":11681,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26032,"lbm_writes_lt_1ms":443,"mutex_wait_us":78,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:41.136343 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:41.188881 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.052s	user 0.024s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20304,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.189421 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:41.202529 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.203238 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:41.348323 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.145s	user 0.116s	sys 0.029s 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":697,"lbm_read_time_us":9554,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30190,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:17:41.349184 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:41.394382 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.045s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22980,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.395031 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:41.406595 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.407229 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:41.552258 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.145s	user 0.116s	sys 0.029s 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":283,"lbm_read_time_us":10352,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26666,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2000}
I20260812 06:17:41.553257 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=10.126437
I20260812 06:17:41.597381 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.044s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18773,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.598110 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:41.613343 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5464,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.613875 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:41.646155 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushMRSOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1259,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2111,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:41.646837 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): free 121006700 bytes of WAL
I20260812 06:17:41.647096 31733 log_reader.cc:385] T ec172c83b7f24fb2bf05bb6ca23d8ecd: removed 12 log segments from log reader
I20260812 06:17:41.647145 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000028 (ops 135-139)
I20260812 06:17:41.647174 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000029 (ops 140-144)
I20260812 06:17:41.647192 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000030 (ops 145-149)
I20260812 06:17:41.647212 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000031 (ops 150-154)
I20260812 06:17:41.647258 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000032 (ops 155-159)
I20260812 06:17:41.647310 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000033 (ops 160-164)
I20260812 06:17:41.647368 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000034 (ops 165-169)
I20260812 06:17:41.647419 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000035 (ops 170-174)
I20260812 06:17:41.647439 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000036 (ops 175-179)
I20260812 06:17:41.647498 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000037 (ops 180-184)
I20260812 06:17:41.647543 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000038 (ops 185-188)
I20260812 06:17:41.647593 31733 log.cc:1079] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: Deleting log segment in path: /tmp/dist-test-taskYoX_Nd/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515450109237-31305-0/minicluster-data/ts-0-root/wals/ec172c83b7f24fb2bf05bb6ca23d8ecd/wal-000000039 (ops 189-193)
I20260812 06:17:41.676818 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: LogGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:41.677469 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:41.695251 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.695720 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=2.188937
I20260812 06:17:41.706825 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4676,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.707346 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=1.000000
I20260812 06:17:41.795918 31305 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.453s	user 1.986s	sys 0.167s
I20260812 06:17:41.890300 31305 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.001s	sys 0.000s
I20260812 06:17:41.890810 31305 tablet_server.cc:179] TabletServer@127.30.146.65:0 shutting down...
I20260812 06:17:41.892326 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: MajorDeltaCompactionOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.185s	user 0.145s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":559,"lbm_read_time_us":13207,"lbm_reads_lt_1ms":670,"lbm_write_time_us":39231,"lbm_writes_lt_1ms":643,"mutex_wait_us":305,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:17:41.895156 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): 463 bytes on disk
I20260812 06:17:41.895658 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: UndoDeltaBlockGCOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.896591 31824 maintenance_manager.cc:419] P 67e1dc411e534f6ba04bc05f2b14fa4b: Scheduling FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd): perf score=6.157687
I20260812 06:17:41.920336 31733 maintenance_manager.cc:643] P 67e1dc411e534f6ba04bc05f2b14fa4b: FlushDeltaMemStoresOp(ec172c83b7f24fb2bf05bb6ca23d8ecd) complete. Timing: real 0.023s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9664,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:41.920995 31305 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:41.921226 31305 tablet_replica.cc:333] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b: stopping tablet replica
I20260812 06:17:41.921365 31305 raft_consensus.cc:2243] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:41.921531 31305 raft_consensus.cc:2272] T ec172c83b7f24fb2bf05bb6ca23d8ecd P 67e1dc411e534f6ba04bc05f2b14fa4b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:41.926369 31305 tablet_server.cc:196] TabletServer@127.30.146.65:0 shutdown complete.
I20260812 06:17:41.943923 31305 master.cc:562] Master@127.30.146.126:38947 shutting down...
I20260812 06:17:41.948339 31305 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:41.948556 31305 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:41.948647 31305 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0d6afb323d7b4a94add27b046375646e: stopping tablet replica
I20260812 06:17:41.962109 31305 master.cc:584] Master@127.30.146.126:38947 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5956 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11943 ms total)

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