[==========] 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:18:57.907505 10218 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.250.190:40657
I20260812 06:18:57.908493 10218 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:18:57.909075 10218 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.915175 10227 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:18:57.915211 10228 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:18:57.915364 10218 server_base.cc:1061] running on GCE node
W20260812 06:18:57.915458 10230 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:18:57.915946 10218 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.916052 10218 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:18:57.916096 10218 hybrid_clock.cc:648] HybridClock initialized: now 1786515537916093 us; error 0 us; skew 500 ppm
I20260812 06:18:57.917855 10218 webserver.cc:533] Webserver started at http://127.9.250.190:34501/ using document root <none> and password file <none>
I20260812 06:18:57.918385 10218 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.918448 10218 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.918676 10218 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.920619 10218 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/master-0-root/instance:
uuid: "ebd1f151d58545b080e178ceb8b327ff"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-21b9"
I20260812 06:18:57.924017 10218 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:18:57.926040 10236 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:18:57.927013 10218 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:18:57.927125 10218 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/master-0-root
uuid: "ebd1f151d58545b080e178ceb8b327ff"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-21b9"
I20260812 06:18:57.927215 10218 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-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:18:57.946445 10218 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.947110 10218 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:18:57.947304 10218 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.954962 10320 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.250.190:40657 every 8 connection(s)
I20260812 06:18:57.954972 10218 rpc_server.cc:307] RPC server started. Bound to: 127.9.250.190:40657
I20260812 06:18:57.957270 10321 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:18:57.962590 10321 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff: Bootstrap starting.
I20260812 06:18:57.965006 10321 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.965966 10321 log.cc:826] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:57.967877 10321 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff: No bootstrap required, opened a new log
I20260812 06:18:57.971004 10321 raft_consensus.cc:359] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ebd1f151d58545b080e178ceb8b327ff" member_type: VOTER }
I20260812 06:18:57.971179 10321 raft_consensus.cc:385] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.971261 10321 raft_consensus.cc:740] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ebd1f151d58545b080e178ceb8b327ff, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.971937 10321 consensus_queue.cc:260] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [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: "ebd1f151d58545b080e178ceb8b327ff" member_type: VOTER }
I20260812 06:18:57.972090 10321 raft_consensus.cc:399] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.972154 10321 raft_consensus.cc:493] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.972275 10321 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.973104 10321 raft_consensus.cc:515] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ebd1f151d58545b080e178ceb8b327ff" member_type: VOTER }
I20260812 06:18:57.973538 10321 leader_election.cc:304] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [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: ebd1f151d58545b080e178ceb8b327ff; no voters: 
I20260812 06:18:57.973865 10321 leader_election.cc:290] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.974001 10327 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.974210 10327 raft_consensus.cc:697] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 1 LEADER]: Becoming Leader. State: Replica: ebd1f151d58545b080e178ceb8b327ff, State: Running, Role: LEADER
I20260812 06:18:57.974649 10327 consensus_queue.cc:237] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [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: "ebd1f151d58545b080e178ceb8b327ff" member_type: VOTER }
I20260812 06:18:57.974807 10321 sys_catalog.cc:565] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:57.976614 10328 sys_catalog.cc:455] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ebd1f151d58545b080e178ceb8b327ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ebd1f151d58545b080e178ceb8b327ff" member_type: VOTER } }
I20260812 06:18:57.976625 10329 sys_catalog.cc:455] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [sys.catalog]: SysCatalogTable state changed. Reason: New leader ebd1f151d58545b080e178ceb8b327ff. Latest consensus state: current_term: 1 leader_uuid: "ebd1f151d58545b080e178ceb8b327ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ebd1f151d58545b080e178ceb8b327ff" member_type: VOTER } }
I20260812 06:18:57.976749 10329 sys_catalog.cc:458] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.976749 10328 sys_catalog.cc:458] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.977105 10343 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:57.977138 10218 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:57.979437 10343 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:57.983886 10343 catalog_manager.cc:1383] Generated new cluster ID: 5f84ff61c13b4e6499059e0813434917
I20260812 06:18:57.983952 10343 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:57.994872 10343 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:57.995719 10343 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:58.005435 10343 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff: Generated new TSK 0
I20260812 06:18:58.006067 10343 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:58.009768 10218 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.012844 10360 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:18:58.013365 10218 server_base.cc:1061] running on GCE node
W20260812 06:18:58.013239 10357 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:18:58.013536 10352 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:18:58.013813 10218 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.013880 10218 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:18:58.013901 10218 hybrid_clock.cc:648] HybridClock initialized: now 1786515538013901 us; error 0 us; skew 500 ppm
I20260812 06:18:58.014860 10218 webserver.cc:533] Webserver started at http://127.9.250.129:39935/ using document root <none> and password file <none>
I20260812 06:18:58.015027 10218 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.015103 10218 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.015183 10218 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.015581 10218 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/instance:
uuid: "ee5e943bb82b4d6fb5bd230a21f60055"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-21b9"
I20260812 06:18:58.016995 10218 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:58.017949 10367 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:18:58.018218 10218 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:58.018291 10218 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root
uuid: "ee5e943bb82b4d6fb5bd230a21f60055"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-21b9"
I20260812 06:18:58.018361 10218 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-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:18:58.024766 10218 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:58.025132 10218 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:58.025570 10218 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:58.026361 10218 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:58.026413 10218 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.026467 10218 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:58.026491 10218 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.032866 10218 rpc_server.cc:307] RPC server started. Bound to: 127.9.250.129:39533
I20260812 06:18:58.032903 10474 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.250.129:39533 every 8 connection(s)
I20260812 06:18:58.042524 10475 heartbeater.cc:344] Connected to a master server at 127.9.250.190:40657
I20260812 06:18:58.042786 10475 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:58.043315 10475 heartbeater.cc:507] Master 127.9.250.190:40657 requested a full tablet report, sending...
I20260812 06:18:58.044724 10266 ts_manager.cc:194] Registered new tserver with Master: ee5e943bb82b4d6fb5bd230a21f60055 (127.9.250.129:39533)
I20260812 06:18:58.044814 10218 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01134711s
I20260812 06:18:58.046247 10266 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54664
I20260812 06:18:58.054100 10266 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54668:
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:18:58.068022 10411 tablet_service.cc:1511] Processing CreateTablet for tablet b60d12df64a4487dadd7c3d95568dfc8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=eeafb69ce45d4918b82b4cfbb97b188e]), partition=
I20260812 06:18:58.068470 10411 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b60d12df64a4487dadd7c3d95568dfc8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:58.070686 10496 tablet_bootstrap.cc:492] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Bootstrap starting.
I20260812 06:18:58.071728 10496 tablet_bootstrap.cc:654] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:58.072809 10496 tablet_bootstrap.cc:492] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: No bootstrap required, opened a new log
I20260812 06:18:58.072898 10496 ts_tablet_manager.cc:1403] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:58.073380 10496 raft_consensus.cc:359] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee5e943bb82b4d6fb5bd230a21f60055" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 39533 } }
I20260812 06:18:58.073513 10496 raft_consensus.cc:385] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:58.073776 10496 raft_consensus.cc:740] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ee5e943bb82b4d6fb5bd230a21f60055, State: Initialized, Role: FOLLOWER
I20260812 06:18:58.073935 10496 consensus_queue.cc:260] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [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: "ee5e943bb82b4d6fb5bd230a21f60055" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 39533 } }
I20260812 06:18:58.074041 10496 raft_consensus.cc:399] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:58.074090 10496 raft_consensus.cc:493] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:58.074137 10496 raft_consensus.cc:3060] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:58.074846 10496 raft_consensus.cc:515] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee5e943bb82b4d6fb5bd230a21f60055" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 39533 } }
I20260812 06:18:58.074971 10496 leader_election.cc:304] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [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: ee5e943bb82b4d6fb5bd230a21f60055; no voters: 
I20260812 06:18:58.075169 10496 leader_election.cc:290] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:58.075340 10502 raft_consensus.cc:2804] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:58.075553 10502 raft_consensus.cc:697] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 1 LEADER]: Becoming Leader. State: Replica: ee5e943bb82b4d6fb5bd230a21f60055, State: Running, Role: LEADER
I20260812 06:18:58.075632 10496 ts_tablet_manager.cc:1434] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:58.075861 10475 heartbeater.cc:499] Master 127.9.250.190:40657 was elected leader, sending a full tablet report...
I20260812 06:18:58.075963 10502 consensus_queue.cc:237] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [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: "ee5e943bb82b4d6fb5bd230a21f60055" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 39533 } }
I20260812 06:18:58.079188 10264 catalog_manager.cc:5719] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 reported cstate change: term changed from 0 to 1, leader changed from <none> to ee5e943bb82b4d6fb5bd230a21f60055 (127.9.250.129). New cstate: current_term: 1 leader_uuid: "ee5e943bb82b4d6fb5bd230a21f60055" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee5e943bb82b4d6fb5bd230a21f60055" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 39533 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:58.143074 10218 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.018s	sys 0.007s
I20260812 06:18:58.283954 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=19.054940
I20260812 06:18:58.448477 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.164s	user 0.136s	sys 0.020s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":629,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1106,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39513,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":138,"threads_started":1,"update_count":1500}
I20260812 06:18:58.449694 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling LogGCOp(b60d12df64a4487dadd7c3d95568dfc8): free 20743880 bytes of WAL
I20260812 06:18:58.450008 10372 log_reader.cc:385] T b60d12df64a4487dadd7c3d95568dfc8: removed 2 log segments from log reader
I20260812 06:18:58.450078 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000001 (ops 1-6)
I20260812 06:18:58.450129 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000002 (ops 7-11)
I20260812 06:18:58.455578 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: LogGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:58.456070 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:58.474314 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.018s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.474912 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:58.613514 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.138s	user 0.107s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":73,"lbm_read_time_us":8362,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21863,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":235,"threads_started":5,"update_count":2000}
I20260812 06:18:58.614099 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8): 16411392 bytes on disk
I20260812 06:18:58.614607 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.615062 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=10.126437
I20260812 06:18:58.654603 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.039s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18304,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.655121 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:58.668121 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.668628 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:58.787454 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.119s	user 0.073s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1721,"lbm_read_time_us":6962,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22678,"lbm_writes_lt_1ms":443,"mutex_wait_us":514,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:18:58.788053 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=10.126437
I20260812 06:18:58.816711 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.028s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12307499,"delete_count":0,"lbm_write_time_us":12166,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.817164 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:58.827381 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.828049 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:58.943493 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.115s	user 0.089s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672286,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":7491,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21379,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:58.944089 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=10.126437
I20260812 06:18:58.989271 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.045s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12755,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.989882 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:59.008311 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.018s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5824,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.008981 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:59.147960 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.139s	user 0.096s	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":926,"lbm_read_time_us":10587,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21671,"lbm_writes_lt_1ms":443,"mutex_wait_us":272,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:18:59.148541 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=10.126437
I20260812 06:18:59.192009 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18647,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.192445 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:59.202525 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.203107 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:59.330205 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.127s	user 0.107s	sys 0.020s 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":616,"lbm_read_time_us":8225,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24559,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:18:59.330689 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=10.126437
I20260812 06:18:59.362651 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.032s	user 0.018s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12002,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.363170 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:59.377740 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.378357 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:59.499753 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.121s	user 0.109s	sys 0.012s 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":277,"lbm_read_time_us":9153,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20987,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":59648,"update_count":2000}
I20260812 06:18:59.500249 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=10.126437
I20260812 06:18:59.545722 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.045s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14643,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.546307 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:59.557035 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.557626 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:59.585316 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1431,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1277,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:59.586196 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8): 447 bytes on disk
I20260812 06:18:59.586645 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.587088 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:59.717175 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.130s	user 0.108s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":675,"lbm_read_time_us":7998,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20740,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:59.717846 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling LogGCOp(b60d12df64a4487dadd7c3d95568dfc8): free 112692367 bytes of WAL
I20260812 06:18:59.718086 10372 log_reader.cc:385] T b60d12df64a4487dadd7c3d95568dfc8: removed 11 log segments from log reader
I20260812 06:18:59.718236 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000003 (ops 12-16)
I20260812 06:18:59.718302 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000004 (ops 17-21)
I20260812 06:18:59.718330 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000005 (ops 22-26)
I20260812 06:18:59.718354 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000006 (ops 27-31)
I20260812 06:18:59.718376 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000007 (ops 32-36)
I20260812 06:18:59.718400 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000008 (ops 37-41)
I20260812 06:18:59.718425 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000009 (ops 42-46)
I20260812 06:18:59.718451 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000010 (ops 47-51)
I20260812 06:18:59.718474 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000011 (ops 52-56)
I20260812 06:18:59.718500 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000012 (ops 57-61)
I20260812 06:18:59.718530 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000013 (ops 62-66)
I20260812 06:18:59.741113 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: LogGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:59.741575 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:18:59.787118 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.045s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20160,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:59.787670 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:18:59.799151 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.799638 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:18:59.978269 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.178s	user 0.092s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":10707,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29670,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":56320,"update_count":2500}
I20260812 06:18:59.978719 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:00.026929 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.048s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18703,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.027532 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:00.043612 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.044039 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:00.205575 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.161s	user 0.118s	sys 0.033s 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":655,"lbm_read_time_us":9167,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30527,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:00.206084 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:00.250823 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.045s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20818,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.251410 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:00.266929 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.267431 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:00.412585 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.145s	user 0.105s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":309,"lbm_read_time_us":8292,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27448,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:00.413187 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:00.456430 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.043s	user 0.020s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.457047 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:00.472863 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.473452 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:00.624519 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.151s	user 0.120s	sys 0.017s 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":644,"lbm_read_time_us":10658,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25336,"lbm_writes_lt_1ms":543,"mutex_wait_us":327,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:00.625181 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:00.671422 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.045s	user 0.029s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18195,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.671955 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:00.819003 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.147s	user 0.095s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":301,"lbm_read_time_us":9197,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24147,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.819602 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:00.877436 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.058s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21142,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.878033 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:00.888581 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.889058 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:00.918144 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.029s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1290,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1396,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:00.918969 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:01.073267 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.154s	user 0.120s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":511,"lbm_read_time_us":12088,"lbm_reads_lt_1ms":564,"lbm_write_time_us":24517,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:19:01.073778 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling LogGCOp(b60d12df64a4487dadd7c3d95568dfc8): free 123804191 bytes of WAL
I20260812 06:19:01.073975 10372 log_reader.cc:385] T b60d12df64a4487dadd7c3d95568dfc8: removed 12 log segments from log reader
I20260812 06:19:01.074015 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000014 (ops 67-71)
I20260812 06:19:01.074051 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000015 (ops 72-76)
I20260812 06:19:01.074080 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000016 (ops 77-81)
I20260812 06:19:01.074155 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000017 (ops 82-86)
I20260812 06:19:01.074190 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000018 (ops 87-91)
I20260812 06:19:01.074213 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000019 (ops 92-96)
I20260812 06:19:01.074265 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000020 (ops 97-100)
I20260812 06:19:01.074296 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000021 (ops 101-105)
I20260812 06:19:01.074347 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000022 (ops 106-110)
I20260812 06:19:01.074375 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000023 (ops 111-115)
I20260812 06:19:01.074433 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000024 (ops 116-120)
I20260812 06:19:01.074465 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000025 (ops 121-124)
I20260812 06:19:01.097218 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: LogGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:01.097640 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8): 463 bytes on disk
I20260812 06:19:01.098197 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.098846 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=15.087375
I20260812 06:19:01.151139 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.052s	user 0.038s	sys 0.007s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":20347,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:01.151650 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=3.181125
I20260812 06:19:01.167898 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4964166,"delete_count":0,"lbm_write_time_us":6545,"lbm_writes_lt_1ms":124,"reinsert_count":0,"update_count":605}
I20260812 06:19:01.168581 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.196750
I20260812 06:19:01.176608 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.008s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":2616,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:01.177121 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:01.364215 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.187s	user 0.151s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877192,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":185,"lbm_read_time_us":13844,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32046,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":3000}
I20260812 06:19:01.364778 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:01.413901 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.049s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17860,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.414443 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:01.424887 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.425515 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:01.591024 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.165s	user 0.123s	sys 0.040s 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":266,"lbm_read_time_us":13232,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24889,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:01.591621 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:01.641248 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.049s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17211,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.641873 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:01.657166 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.657693 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:01.824903 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.167s	user 0.118s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":679,"lbm_read_time_us":13564,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27052,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:19:01.825567 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=11.118625
I20260812 06:19:01.860697 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.033s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13990,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:01.861267 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:01.887082 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.025s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4677,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.887624 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:01.903303 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.903947 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:02.069516 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.165s	user 0.109s	sys 0.054s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":121,"lbm_read_time_us":11257,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27044,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:02.070168 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:02.116875 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.047s	user 0.028s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16284,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.117444 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:02.140264 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.023s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.140975 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:02.318482 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.177s	user 0.093s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":795,"lbm_read_time_us":10643,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28698,"lbm_writes_lt_1ms":543,"mutex_wait_us":246,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:19:02.319216 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:02.360347 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.041s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17540,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.360913 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:02.376492 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.377082 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:02.416550 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushMRSOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.039s	user 0.029s	sys 0.009s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1207,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2023,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:02.417464 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling LogGCOp(b60d12df64a4487dadd7c3d95568dfc8): free 129320714 bytes of WAL
I20260812 06:19:02.417726 10372 log_reader.cc:385] T b60d12df64a4487dadd7c3d95568dfc8: removed 13 log segments from log reader
I20260812 06:19:02.417791 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000026 (ops 125-129)
I20260812 06:19:02.417840 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000027 (ops 130-134)
I20260812 06:19:02.417876 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000028 (ops 135-139)
I20260812 06:19:02.417912 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000029 (ops 140-144)
I20260812 06:19:02.417941 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000030 (ops 145-148)
I20260812 06:19:02.417974 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000031 (ops 149-153)
I20260812 06:19:02.418004 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000032 (ops 154-158)
I20260812 06:19:02.418032 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000033 (ops 159-162)
I20260812 06:19:02.418061 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000034 (ops 163-167)
I20260812 06:19:02.418088 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000035 (ops 168-172)
I20260812 06:19:02.418123 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000036 (ops 173-177)
I20260812 06:19:02.418154 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000037 (ops 178-182)
I20260812 06:19:02.418180 10372 log.cc:1079] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/b60d12df64a4487dadd7c3d95568dfc8/wal-000000038 (ops 183-187)
I20260812 06:19:02.445389 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: LogGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:02.445940 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=3.181125
I20260812 06:19:02.460615 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.015s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:02.461124 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:02.648034 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.187s	user 0.128s	sys 0.056s Metrics: {"cfile_cache_miss":643,"cfile_cache_miss_bytes":29287459,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":257,"lbm_read_time_us":13348,"lbm_reads_lt_1ms":675,"lbm_write_time_us":31097,"lbm_writes_lt_1ms":653,"mutex_wait_us":466,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":571136,"thread_start_us":91,"threads_started":1,"update_count":3050}
I20260812 06:19:02.648689 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=14.095187
I20260812 06:19:02.701997 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.053s	user 0.025s	sys 0.026s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19666,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.702666 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8): 481 bytes on disk
I20260812 06:19:02.703212 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: UndoDeltaBlockGCOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.703873 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:02.727805 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.728318 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=2.188937
I20260812 06:19:02.737586 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: FlushDeltaMemStoresOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3334,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.738045 10476 maintenance_manager.cc:419] P ee5e943bb82b4d6fb5bd230a21f60055: Scheduling MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8): perf score=1.000000
I20260812 06:19:02.780181 10218 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.637s	user 1.704s	sys 0.132s
I20260812 06:19:02.877647 10218 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.097s	user 0.002s	sys 0.000s
I20260812 06:19:02.878283 10218 tablet_server.cc:179] TabletServer@127.9.250.129:0 shutting down...
I20260812 06:19:02.918181 10372 maintenance_manager.cc:643] P ee5e943bb82b4d6fb5bd230a21f60055: MajorDeltaCompactionOp(b60d12df64a4487dadd7c3d95568dfc8) complete. Timing: real 0.180s	user 0.120s	sys 0.060s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28466963,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":231,"lbm_read_time_us":12683,"lbm_reads_lt_1ms":659,"lbm_write_time_us":29715,"lbm_writes_lt_1ms":633,"mutex_wait_us":40,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2950}
I20260812 06:19:02.918864 10218 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:02.919257 10218 tablet_replica.cc:333] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055: stopping tablet replica
I20260812 06:19:02.919548 10218 raft_consensus.cc:2243] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.919804 10218 raft_consensus.cc:2272] T b60d12df64a4487dadd7c3d95568dfc8 P ee5e943bb82b4d6fb5bd230a21f60055 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.936239 10218 tablet_server.cc:196] TabletServer@127.9.250.129:0 shutdown complete.
I20260812 06:19:02.969022 10218 master.cc:562] Master@127.9.250.190:40657 shutting down...
I20260812 06:19:02.972098 10218 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.972277 10218 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.972345 10218 tablet_replica.cc:333] T 00000000000000000000000000000000 P ebd1f151d58545b080e178ceb8b327ff: stopping tablet replica
I20260812 06:19:02.984462 10218 master.cc:584] Master@127.9.250.190:40657 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5148 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:03.066006 10218 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.250.190:41909
I20260812 06:19:03.066442 10218 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:03.068439 10527 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.068476 10218 server_base.cc:1061] running on GCE node
W20260812 06:19:03.068645 10525 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.068657 10523 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.068877 10218 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.068920 10218 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:03.068934 10218 hybrid_clock.cc:648] HybridClock initialized: now 1786515543068934 us; error 0 us; skew 500 ppm
I20260812 06:19:03.069751 10218 webserver.cc:533] Webserver started at http://127.9.250.190:33655/ using document root <none> and password file <none>
I20260812 06:19:03.069907 10218 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.069957 10218 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.070034 10218 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.070410 10218 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/master-0-root/instance:
uuid: "5acd3d25ca4b4088a2c0cf7715edb681"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-21b9"
I20260812 06:19:03.072127 10218 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:03.072975 10540 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.073189 10218 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:03.073256 10218 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/master-0-root
uuid: "5acd3d25ca4b4088a2c0cf7715edb681"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-21b9"
I20260812 06:19:03.073328 10218 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:03.089993 10218 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.090404 10218 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.094445 10218 rpc_server.cc:307] RPC server started. Bound to: 127.9.250.190:41909
I20260812 06:19:03.098834 10634 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.250.190:41909 every 8 connection(s)
I20260812 06:19:03.099320 10640 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:03.101058 10640 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681: Bootstrap starting.
I20260812 06:19:03.101794 10640 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.102726 10640 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681: No bootstrap required, opened a new log
I20260812 06:19:03.103072 10640 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5acd3d25ca4b4088a2c0cf7715edb681" member_type: VOTER }
I20260812 06:19:03.103155 10640 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.103183 10640 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5acd3d25ca4b4088a2c0cf7715edb681, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.103303 10640 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [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: "5acd3d25ca4b4088a2c0cf7715edb681" member_type: VOTER }
I20260812 06:19:03.103365 10640 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.103392 10640 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.103425 10640 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.104053 10640 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5acd3d25ca4b4088a2c0cf7715edb681" member_type: VOTER }
I20260812 06:19:03.104166 10640 leader_election.cc:304] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [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: 5acd3d25ca4b4088a2c0cf7715edb681; no voters: 
I20260812 06:19:03.104308 10640 leader_election.cc:290] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.104432 10644 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.104624 10644 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 1 LEADER]: Becoming Leader. State: Replica: 5acd3d25ca4b4088a2c0cf7715edb681, State: Running, Role: LEADER
I20260812 06:19:03.104779 10640 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:03.104791 10644 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [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: "5acd3d25ca4b4088a2c0cf7715edb681" member_type: VOTER }
I20260812 06:19:03.105247 10645 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5acd3d25ca4b4088a2c0cf7715edb681" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5acd3d25ca4b4088a2c0cf7715edb681" member_type: VOTER } }
I20260812 06:19:03.105269 10646 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5acd3d25ca4b4088a2c0cf7715edb681. Latest consensus state: current_term: 1 leader_uuid: "5acd3d25ca4b4088a2c0cf7715edb681" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5acd3d25ca4b4088a2c0cf7715edb681" member_type: VOTER } }
I20260812 06:19:03.105412 10645 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.105444 10646 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.105893 10652 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:03.106766 10652 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:03.106967 10218 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:03.108501 10652 catalog_manager.cc:1383] Generated new cluster ID: 0cd78ab57d044443a8b46ae2dd204637
I20260812 06:19:03.108560 10652 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:03.133513 10652 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:03.134085 10652 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:03.146728 10652 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681: Generated new TSK 0
I20260812 06:19:03.146912 10652 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:03.171566 10218 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:03.173578 10672 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.173739 10673 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.173575 10676 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.173682 10218 server_base.cc:1061] running on GCE node
I20260812 06:19:03.173970 10218 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.174014 10218 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:03.174036 10218 hybrid_clock.cc:648] HybridClock initialized: now 1786515543174035 us; error 0 us; skew 500 ppm
I20260812 06:19:03.174868 10218 webserver.cc:533] Webserver started at http://127.9.250.129:35191/ using document root <none> and password file <none>
I20260812 06:19:03.175040 10218 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.175094 10218 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.175171 10218 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.175598 10218 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/instance:
uuid: "f1319f13cb19447ca8d8a2117d9434c2"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-21b9"
I20260812 06:19:03.177023 10218 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:03.178023 10692 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.178289 10218 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:03.178375 10218 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root
uuid: "f1319f13cb19447ca8d8a2117d9434c2"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-21b9"
I20260812 06:19:03.178484 10218 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:03.184703 10218 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.185006 10218 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.185263 10218 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:03.185710 10218 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:03.185760 10218 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.185806 10218 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:03.185833 10218 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.189775 10218 rpc_server.cc:307] RPC server started. Bound to: 127.9.250.129:38143
I20260812 06:19:03.190536 10813 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.250.129:38143 every 8 connection(s)
I20260812 06:19:03.198312 10814 heartbeater.cc:344] Connected to a master server at 127.9.250.190:41909
I20260812 06:19:03.198421 10814 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:03.198657 10814 heartbeater.cc:507] Master 127.9.250.190:41909 requested a full tablet report, sending...
I20260812 06:19:03.199254 10579 ts_manager.cc:194] Registered new tserver with Master: f1319f13cb19447ca8d8a2117d9434c2 (127.9.250.129:38143)
I20260812 06:19:03.199991 10579 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56298
I20260812 06:19:03.200222 10218 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009848269s
I20260812 06:19:03.206761 10579 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56300:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:03.214902 10743 tablet_service.cc:1511] Processing CreateTablet for tablet f6bcef6ba6c042bab75fe1cfea27bbb7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=edcb7a1a2e06487fb76199be51caa4c5]), partition=
I20260812 06:19:03.215161 10743 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f6bcef6ba6c042bab75fe1cfea27bbb7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:03.217324 10837 tablet_bootstrap.cc:492] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Bootstrap starting.
I20260812 06:19:03.218178 10837 tablet_bootstrap.cc:654] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.219414 10837 tablet_bootstrap.cc:492] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: No bootstrap required, opened a new log
I20260812 06:19:03.219506 10837 ts_tablet_manager.cc:1403] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:03.219930 10837 raft_consensus.cc:359] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f1319f13cb19447ca8d8a2117d9434c2" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 38143 } }
I20260812 06:19:03.220021 10837 raft_consensus.cc:385] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.220050 10837 raft_consensus.cc:740] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f1319f13cb19447ca8d8a2117d9434c2, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.220172 10837 consensus_queue.cc:260] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [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: "f1319f13cb19447ca8d8a2117d9434c2" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 38143 } }
I20260812 06:19:03.220242 10837 raft_consensus.cc:399] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.220299 10837 raft_consensus.cc:493] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.220351 10837 raft_consensus.cc:3060] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.221056 10837 raft_consensus.cc:515] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f1319f13cb19447ca8d8a2117d9434c2" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 38143 } }
I20260812 06:19:03.221187 10837 leader_election.cc:304] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [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: f1319f13cb19447ca8d8a2117d9434c2; no voters: 
I20260812 06:19:03.221369 10837 leader_election.cc:290] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.221467 10840 raft_consensus.cc:2804] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.221652 10837 ts_tablet_manager.cc:1434] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:03.221683 10840 raft_consensus.cc:697] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 1 LEADER]: Becoming Leader. State: Replica: f1319f13cb19447ca8d8a2117d9434c2, State: Running, Role: LEADER
I20260812 06:19:03.221679 10814 heartbeater.cc:499] Master 127.9.250.190:41909 was elected leader, sending a full tablet report...
I20260812 06:19:03.221850 10840 consensus_queue.cc:237] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [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: "f1319f13cb19447ca8d8a2117d9434c2" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 38143 } }
I20260812 06:19:03.223100 10579 catalog_manager.cc:5719] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 reported cstate change: term changed from 0 to 1, leader changed from <none> to f1319f13cb19447ca8d8a2117d9434c2 (127.9.250.129). New cstate: current_term: 1 leader_uuid: "f1319f13cb19447ca8d8a2117d9434c2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f1319f13cb19447ca8d8a2117d9434c2" member_type: VOTER last_known_addr { host: "127.9.250.129" port: 38143 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:03.280462 10218 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.008s	sys 0.014s
I20260812 06:19:03.441010 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=23.023690
I20260812 06:19:03.592845 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.152s	user 0.107s	sys 0.044s Metrics: {"bytes_written":12635684,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1127,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39760,"lbm_writes_lt_1ms":865,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":2816,"update_count":1540}
I20260812 06:19:03.593576 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): free 20743880 bytes of WAL
I20260812 06:19:03.593888 10702 log_reader.cc:385] T f6bcef6ba6c042bab75fe1cfea27bbb7: removed 2 log segments from log reader
I20260812 06:19:03.593950 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000001 (ops 1-6)
I20260812 06:19:03.593992 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000002 (ops 7-11)
I20260812 06:19:03.597769 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:03.598212 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): 20513814 bytes on disk
I20260812 06:19:03.598680 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.599154 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:03.614099 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.015s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4481,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:03.614563 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:03.750908 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.136s	user 0.098s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713266,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":519,"lbm_read_time_us":11382,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20661,"lbm_writes_lt_1ms":443,"mutex_wait_us":5,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":333,"threads_started":5,"update_count":2000}
I20260812 06:19:03.751564 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=11.118625
I20260812 06:19:03.786623 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.035s	user 0.013s	sys 0.018s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":11782,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:03.787195 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:03.797976 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.798457 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:03.946940 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.148s	user 0.083s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":806,"lbm_read_time_us":10155,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24978,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:03.947495 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:03.985801 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.038s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16557,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.986331 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:03.997915 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.998355 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:04.117502 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.119s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":878,"lbm_read_time_us":8238,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22136,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:19:04.118037 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:04.154671 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.036s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13369,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.155221 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:04.165462 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.165962 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:04.287424 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.121s	user 0.088s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":763,"lbm_read_time_us":7487,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22138,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35456,"update_count":2000}
I20260812 06:19:04.287972 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:04.335248 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.047s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15900,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.335834 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:04.346305 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.346742 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:04.487428 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.141s	user 0.105s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":10356,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21459,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":75392,"update_count":2000}
I20260812 06:19:04.488234 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:04.531668 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.043s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21977,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.532119 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:04.543380 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.543815 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:04.671487 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.128s	user 0.101s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":9238,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24162,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:04.672075 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:04.711932 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.040s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16457,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.712455 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:04.727941 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.728530 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:04.760192 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1447,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1922,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:04.760775 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): free 112692369 bytes of WAL
I20260812 06:19:04.760988 10702 log_reader.cc:385] T f6bcef6ba6c042bab75fe1cfea27bbb7: removed 11 log segments from log reader
I20260812 06:19:04.761040 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000003 (ops 12-16)
I20260812 06:19:04.761070 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000004 (ops 17-21)
I20260812 06:19:04.761101 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000005 (ops 22-26)
I20260812 06:19:04.761132 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000006 (ops 27-31)
I20260812 06:19:04.761164 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000007 (ops 32-36)
I20260812 06:19:04.761197 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000008 (ops 37-41)
I20260812 06:19:04.761229 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000009 (ops 42-46)
I20260812 06:19:04.761260 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000010 (ops 47-51)
I20260812 06:19:04.761289 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000011 (ops 52-56)
I20260812 06:19:04.761320 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000012 (ops 57-61)
I20260812 06:19:04.761351 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000013 (ops 62-66)
I20260812 06:19:04.781029 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.020s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:19:04.781538 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=3.181125
I20260812 06:19:04.802580 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.021s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6312,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.803006 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): 447 bytes on disk
I20260812 06:19:04.803401 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) 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:19:04.803836 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:04.813079 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3278,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.813537 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:04.977200 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.163s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918319,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2468,"lbm_read_time_us":11019,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32451,"lbm_writes_lt_1ms":643,"mutex_wait_us":1803,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:19:04.977758 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=14.095187
I20260812 06:19:05.020339 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.042s	user 0.017s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17969,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.020889 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:05.032433 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4097,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.032907 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:05.195009 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.162s	user 0.118s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":11384,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27716,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:19:05.195663 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=14.095187
I20260812 06:19:05.238572 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.043s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18848,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.239022 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:05.380890 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.142s	user 0.114s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1042,"lbm_read_time_us":8669,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25592,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:19:05.381434 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:05.411324 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.030s	user 0.026s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12580,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.411782 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:05.422294 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.422902 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:05.539678 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.117s	user 0.094s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":655,"lbm_read_time_us":7583,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21134,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:19:05.540189 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:05.590555 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.050s	user 0.017s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17383,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.591133 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:05.601190 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.601801 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:05.722882 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.121s	user 0.093s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":7934,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22749,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":89216,"update_count":2000}
I20260812 06:19:05.723459 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:05.765673 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.042s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15199,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.766238 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:05.776516 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.777151 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:05.893215 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.116s	user 0.089s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1002,"lbm_read_time_us":7820,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20985,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.893798 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:05.936513 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.043s	user 0.018s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12626,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.937165 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:05.952605 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.953176 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:06.098377 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.145s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":9956,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22612,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:19:06.099027 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:06.143988 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.045s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16674,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.144466 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:06.157292 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.159648 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:06.186331 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1482,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1491,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:06.187036 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): free 136728185 bytes of WAL
I20260812 06:19:06.187321 10702 log_reader.cc:385] T f6bcef6ba6c042bab75fe1cfea27bbb7: removed 13 log segments from log reader
I20260812 06:19:06.187376 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000014 (ops 67-71)
I20260812 06:19:06.187407 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000015 (ops 72-76)
I20260812 06:19:06.187439 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000016 (ops 77-81)
I20260812 06:19:06.187471 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000017 (ops 82-86)
I20260812 06:19:06.187513 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000018 (ops 87-91)
I20260812 06:19:06.187546 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000019 (ops 92-96)
I20260812 06:19:06.187577 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000020 (ops 97-101)
I20260812 06:19:06.187608 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000021 (ops 102-106)
I20260812 06:19:06.187639 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000022 (ops 107-111)
I20260812 06:19:06.187670 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000023 (ops 112-116)
I20260812 06:19:06.187701 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000024 (ops 117-121)
I20260812 06:19:06.187733 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000025 (ops 122-126)
I20260812 06:19:06.187765 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000026 (ops 127-131)
I20260812 06:19:06.212105 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:06.212533 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=3.181125
I20260812 06:19:06.233783 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.021s	user 0.001s	sys 0.017s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:06.234328 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:06.248503 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5241,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.249017 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): 482 bytes on disk
I20260812 06:19:06.249552 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.250119 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:06.439390 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.189s	user 0.122s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4944,"lbm_read_time_us":13909,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28399,"lbm_writes_lt_1ms":643,"mutex_wait_us":2186,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:19:06.439994 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=14.095187
I20260812 06:19:06.488606 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.048s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16834,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.489202 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:06.499771 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.500204 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:06.676429 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.176s	user 0.115s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":12359,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25854,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:19:06.676976 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=14.095187
I20260812 06:19:06.723598 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.046s	user 0.011s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.724129 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:06.743219 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.019s	user 0.000s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.743917 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:06.908320 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.164s	user 0.111s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":825,"lbm_read_time_us":11542,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26464,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:06.908875 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=11.118625
I20260812 06:19:06.945744 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.037s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15511,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.946316 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:06.971068 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.025s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.971603 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:06.986449 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.986974 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:07.149390 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.162s	user 0.113s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":821,"lbm_read_time_us":9891,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24322,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:07.149866 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=14.095187
I20260812 06:19:07.195710 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.046s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21530,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.196244 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:07.206856 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.207459 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:07.339804 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.132s	user 0.109s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":405,"lbm_read_time_us":8368,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25506,"lbm_writes_lt_1ms":543,"mutex_wait_us":194,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:07.340335 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=11.118625
I20260812 06:19:07.368443 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11476,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:07.369239 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:07.382381 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.382959 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:07.503233 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.120s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":54,"lbm_read_time_us":7687,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21576,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:07.503888 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=10.126437
I20260812 06:19:07.543181 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.039s	user 0.013s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13077,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.543732 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:07.553444 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.554162 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:07.584895 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushMRSOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.030s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1270,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1861,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:07.585530 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): free 120553636 bytes of WAL
I20260812 06:19:07.585738 10702 log_reader.cc:385] T f6bcef6ba6c042bab75fe1cfea27bbb7: removed 12 log segments from log reader
I20260812 06:19:07.585784 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000027 (ops 132-136)
I20260812 06:19:07.585813 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000028 (ops 137-141)
I20260812 06:19:07.585843 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000029 (ops 142-146)
I20260812 06:19:07.585875 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000030 (ops 147-151)
I20260812 06:19:07.585908 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000031 (ops 152-156)
I20260812 06:19:07.585942 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000032 (ops 157-161)
I20260812 06:19:07.585973 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000033 (ops 162-166)
I20260812 06:19:07.586002 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000034 (ops 167-170)
I20260812 06:19:07.586035 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000035 (ops 171-175)
I20260812 06:19:07.586066 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000036 (ops 176-180)
I20260812 06:19:07.586097 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000037 (ops 181-184)
I20260812 06:19:07.586128 10702 log.cc:1079] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: Deleting log segment in path: /tmp/dist-test-taskVgjpMs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537896531-10218-0/minicluster-data/ts-0-root/wals/f6bcef6ba6c042bab75fe1cfea27bbb7/wal-000000038 (ops 185-189)
I20260812 06:19:07.607017 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: LogGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:19:07.607430 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7): 472 bytes on disk
I20260812 06:19:07.607993 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: UndoDeltaBlockGCOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.608657 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:07.626709 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.627195 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=2.188937
I20260812 06:19:07.636752 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.637336 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=1.000000
I20260812 06:19:07.801517 10218 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.521s	user 1.682s	sys 0.132s
I20260812 06:19:07.804560 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: MajorDeltaCompactionOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.167s	user 0.114s	sys 0.046s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1063,"lbm_read_time_us":12195,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30452,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10240,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:19:07.805100 10816 maintenance_manager.cc:419] P f1319f13cb19447ca8d8a2117d9434c2: Scheduling FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7): perf score=14.095187
I20260812 06:19:07.832453 10218 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.031s	user 0.002s	sys 0.000s
I20260812 06:19:07.835471 10218 tablet_server.cc:179] TabletServer@127.9.250.129:0 shutting down...
I20260812 06:19:07.850268 10702 maintenance_manager.cc:643] P f1319f13cb19447ca8d8a2117d9434c2: FlushDeltaMemStoresOp(f6bcef6ba6c042bab75fe1cfea27bbb7) complete. Timing: real 0.045s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19548,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.850843 10218 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:07.851086 10218 tablet_replica.cc:333] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2: stopping tablet replica
I20260812 06:19:07.851202 10218 raft_consensus.cc:2243] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.851377 10218 raft_consensus.cc:2272] T f6bcef6ba6c042bab75fe1cfea27bbb7 P f1319f13cb19447ca8d8a2117d9434c2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.864598 10218 tablet_server.cc:196] TabletServer@127.9.250.129:0 shutdown complete.
I20260812 06:19:07.867177 10218 master.cc:562] Master@127.9.250.190:41909 shutting down...
I20260812 06:19:07.870141 10218 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.870298 10218 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.870358 10218 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5acd3d25ca4b4088a2c0cf7715edb681: stopping tablet replica
I20260812 06:19:07.882550 10218 master.cc:584] Master@127.9.250.190:41909 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4898 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10047 ms total)

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