[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:58.099089 23390 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.215.190:43515
I20260812 06:17:58.100186 23390 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:58.100848 23390 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:58.108151 23408 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:58.108165 23405 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:58.108364 23406 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:58.108530 23390 server_base.cc:1061] running on GCE node
I20260812 06:17:58.109115 23390 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:58.109249 23390 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:58.109319 23390 hybrid_clock.cc:648] HybridClock initialized: now 1786515478109315 us; error 0 us; skew 500 ppm
I20260812 06:17:58.111498 23390 webserver.cc:533] Webserver started at http://127.22.215.190:38159/ using document root <none> and password file <none>
I20260812 06:17:58.112131 23390 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:58.112246 23390 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:58.112555 23390 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:58.114729 23390 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/master-0-root/instance:
uuid: "b987b4c99da745b69ff96892de384e2f"
format_stamp: "Formatted at 2026-08-12 06:17:58 on dist-test-slave-zr1t"
I20260812 06:17:58.118789 23390 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:58.121281 23413 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:58.122529 23390 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:58.122696 23390 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/master-0-root
uuid: "b987b4c99da745b69ff96892de384e2f"
format_stamp: "Formatted at 2026-08-12 06:17:58 on dist-test-slave-zr1t"
I20260812 06:17:58.122826 23390 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:58.146380 23390 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:58.147185 23390 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:58.147419 23390 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:58.156829 23390 rpc_server.cc:307] RPC server started. Bound to: 127.22.215.190:43515
I20260812 06:17:58.156877 23500 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.215.190:43515 every 8 connection(s)
I20260812 06:17:58.159456 23501 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:58.166127 23501 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f: Bootstrap starting.
I20260812 06:17:58.168744 23501 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:58.169811 23501 log.cc:826] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:58.172112 23501 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f: No bootstrap required, opened a new log
I20260812 06:17:58.175230 23501 raft_consensus.cc:359] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b987b4c99da745b69ff96892de384e2f" member_type: VOTER }
I20260812 06:17:58.175414 23501 raft_consensus.cc:385] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:58.175495 23501 raft_consensus.cc:740] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b987b4c99da745b69ff96892de384e2f, State: Initialized, Role: FOLLOWER
I20260812 06:17:58.176225 23501 consensus_queue.cc:260] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [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: "b987b4c99da745b69ff96892de384e2f" member_type: VOTER }
I20260812 06:17:58.176380 23501 raft_consensus.cc:399] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:58.176486 23501 raft_consensus.cc:493] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:58.176795 23501 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:58.177876 23501 raft_consensus.cc:515] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b987b4c99da745b69ff96892de384e2f" member_type: VOTER }
I20260812 06:17:58.178476 23501 leader_election.cc:304] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [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: b987b4c99da745b69ff96892de384e2f; no voters: 
I20260812 06:17:58.178875 23501 leader_election.cc:290] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:58.179061 23506 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:58.179322 23506 raft_consensus.cc:697] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 1 LEADER]: Becoming Leader. State: Replica: b987b4c99da745b69ff96892de384e2f, State: Running, Role: LEADER
I20260812 06:17:58.179824 23506 consensus_queue.cc:237] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [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: "b987b4c99da745b69ff96892de384e2f" member_type: VOTER }
I20260812 06:17:58.180006 23501 sys_catalog.cc:565] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:58.181946 23508 sys_catalog.cc:455] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [sys.catalog]: SysCatalogTable state changed. Reason: New leader b987b4c99da745b69ff96892de384e2f. Latest consensus state: current_term: 1 leader_uuid: "b987b4c99da745b69ff96892de384e2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b987b4c99da745b69ff96892de384e2f" member_type: VOTER } }
I20260812 06:17:58.182063 23508 sys_catalog.cc:458] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:58.181914 23507 sys_catalog.cc:455] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b987b4c99da745b69ff96892de384e2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b987b4c99da745b69ff96892de384e2f" member_type: VOTER } }
I20260812 06:17:58.182175 23507 sys_catalog.cc:458] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:58.182512 23390 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:58.182716 23527 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:58.185336 23527 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:58.190676 23527 catalog_manager.cc:1383] Generated new cluster ID: f3f8bf1a437b49f4853c6d4f0133032d
I20260812 06:17:58.190768 23527 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:58.220220 23527 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:58.221170 23527 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:58.226747 23527 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f: Generated new TSK 0
I20260812 06:17:58.227521 23527 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:58.247792 23390 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:58.251276 23538 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:58.251335 23539 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:58.251523 23390 server_base.cc:1061] running on GCE node
W20260812 06:17:58.251286 23543 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:58.251845 23390 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:58.251895 23390 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:58.251926 23390 hybrid_clock.cc:648] HybridClock initialized: now 1786515478251913 us; error 0 us; skew 500 ppm
I20260812 06:17:58.253119 23390 webserver.cc:533] Webserver started at http://127.22.215.129:40319/ using document root <none> and password file <none>
I20260812 06:17:58.253337 23390 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:58.253405 23390 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:58.253547 23390 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:58.254163 23390 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/instance:
uuid: "be308f2c552841a3b20007bd759f6d88"
format_stamp: "Formatted at 2026-08-12 06:17:58 on dist-test-slave-zr1t"
I20260812 06:17:58.256044 23390 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:58.257165 23548 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:58.257416 23390 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:58.257500 23390 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root
uuid: "be308f2c552841a3b20007bd759f6d88"
format_stamp: "Formatted at 2026-08-12 06:17:58 on dist-test-slave-zr1t"
I20260812 06:17:58.257623 23390 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:58.282835 23390 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:58.283354 23390 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:58.283917 23390 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:58.284873 23390 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:58.284929 23390 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:58.285001 23390 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:58.285043 23390 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:58.292086 23390 rpc_server.cc:307] RPC server started. Bound to: 127.22.215.129:35561
I20260812 06:17:58.292152 23653 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.215.129:35561 every 8 connection(s)
I20260812 06:17:58.302637 23654 heartbeater.cc:344] Connected to a master server at 127.22.215.190:43515
I20260812 06:17:58.302913 23654 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:58.303357 23654 heartbeater.cc:507] Master 127.22.215.190:43515 requested a full tablet report, sending...
I20260812 06:17:58.305011 23444 ts_manager.cc:194] Registered new tserver with Master: be308f2c552841a3b20007bd759f6d88 (127.22.215.129:35561)
I20260812 06:17:58.305190 23390 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012424238s
I20260812 06:17:58.306604 23444 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55750
I20260812 06:17:58.316469 23444 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55766:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:58.333395 23595 tablet_service.cc:1511] Processing CreateTablet for tablet 4c4bb87bd9a74ad39e349330c615f06e (DEFAULT_TABLE table=heavy-update-compaction-test [id=ebfe81ef1ab044be82e4d8272dfff52a]), partition=
I20260812 06:17:58.334034 23595 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4c4bb87bd9a74ad39e349330c615f06e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:58.336719 23670 tablet_bootstrap.cc:492] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Bootstrap starting.
I20260812 06:17:58.338289 23670 tablet_bootstrap.cc:654] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:58.339609 23670 tablet_bootstrap.cc:492] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: No bootstrap required, opened a new log
I20260812 06:17:58.339707 23670 ts_tablet_manager.cc:1403] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:58.340286 23670 raft_consensus.cc:359] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be308f2c552841a3b20007bd759f6d88" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 35561 } }
I20260812 06:17:58.340412 23670 raft_consensus.cc:385] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:58.340441 23670 raft_consensus.cc:740] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: be308f2c552841a3b20007bd759f6d88, State: Initialized, Role: FOLLOWER
I20260812 06:17:58.340644 23670 consensus_queue.cc:260] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [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: "be308f2c552841a3b20007bd759f6d88" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 35561 } }
I20260812 06:17:58.340727 23670 raft_consensus.cc:399] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:58.340780 23670 raft_consensus.cc:493] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:58.340847 23670 raft_consensus.cc:3060] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:58.342056 23670 raft_consensus.cc:515] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be308f2c552841a3b20007bd759f6d88" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 35561 } }
I20260812 06:17:58.342192 23670 leader_election.cc:304] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [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: be308f2c552841a3b20007bd759f6d88; no voters: 
I20260812 06:17:58.342530 23670 leader_election.cc:290] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:58.342664 23673 raft_consensus.cc:2804] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:58.342875 23673 raft_consensus.cc:697] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 1 LEADER]: Becoming Leader. State: Replica: be308f2c552841a3b20007bd759f6d88, State: Running, Role: LEADER
I20260812 06:17:58.342993 23670 ts_tablet_manager.cc:1434] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:58.343109 23673 consensus_queue.cc:237] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [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: "be308f2c552841a3b20007bd759f6d88" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 35561 } }
I20260812 06:17:58.343356 23654 heartbeater.cc:499] Master 127.22.215.190:43515 was elected leader, sending a full tablet report...
I20260812 06:17:58.346606 23444 catalog_manager.cc:5719] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 reported cstate change: term changed from 0 to 1, leader changed from <none> to be308f2c552841a3b20007bd759f6d88 (127.22.215.129). New cstate: current_term: 1 leader_uuid: "be308f2c552841a3b20007bd759f6d88" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be308f2c552841a3b20007bd759f6d88" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 35561 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:58.411733 23390 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.021s	sys 0.004s
I20260812 06:17:58.543478 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=15.086190
I20260812 06:17:58.719337 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.175s	user 0.157s	sys 0.016s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":263,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":863,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42976,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":121,"threads_started":1,"update_count":1450}
I20260812 06:17:58.720667 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling LogGCOp(4c4bb87bd9a74ad39e349330c615f06e): free 20743880 bytes of WAL
I20260812 06:17:58.720993 23556 log_reader.cc:385] T 4c4bb87bd9a74ad39e349330c615f06e: removed 2 log segments from log reader
I20260812 06:17:58.721055 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000001 (ops 1-6)
I20260812 06:17:58.721109 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000002 (ops 7-11)
I20260812 06:17:58.727721 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: LogGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:58.728395 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:17:58.748229 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.748872 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e): 12719216 bytes on disk
I20260812 06:17:58.749838 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.750401 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:17:58.896663 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.146s	user 0.115s	sys 0.031s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262037,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":9586,"lbm_reads_lt_1ms":450,"lbm_write_time_us":26803,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":329,"threads_started":5,"update_count":1950}
I20260812 06:17:58.897315 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:17:58.938675 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.041s	user 0.016s	sys 0.024s Metrics: {"bytes_written":12348517,"delete_count":0,"lbm_write_time_us":18438,"lbm_writes_lt_1ms":304,"reinsert_count":0,"update_count":1505}
I20260812 06:17:58.939199 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:17:58.952461 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:58.953379 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:17:59.096077 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.142s	user 0.102s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":10129,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28036,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:17:59.096732 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:17:59.143069 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18389,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.143544 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:17:59.154866 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.155642 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:17:59.289465 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.134s	user 0.112s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1203,"lbm_read_time_us":8460,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26525,"lbm_writes_lt_1ms":443,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:17:59.290081 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:17:59.348006 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.058s	user 0.022s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17370,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.348570 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:17:59.360273 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.360872 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:17:59.527573 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.167s	user 0.104s	sys 0.059s 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":956,"lbm_read_time_us":11335,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28749,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:17:59.528350 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:17:59.577826 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.049s	user 0.037s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18898,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.578622 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:17:59.589769 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.590247 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:17:59.720208 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.130s	user 0.094s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":157,"lbm_read_time_us":10522,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23602,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22400,"update_count":2000}
I20260812 06:17:59.720811 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:17:59.767805 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.047s	user 0.014s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17430,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.768435 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:17:59.780967 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.781476 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:17:59.920064 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.138s	user 0.114s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":807,"lbm_read_time_us":10656,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25845,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:17:59.920874 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:17:59.973124 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.052s	user 0.025s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17966,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.973944 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:17:59.985435 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.985966 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:00.142429 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.156s	user 0.120s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":12568,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24509,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:18:00.143211 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:18:00.193092 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.050s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19479,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.193727 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:00.205101 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.205816 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:00.239648 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.034s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1349,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2031,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:00.240621 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling LogGCOp(4c4bb87bd9a74ad39e349330c615f06e): free 124257250 bytes of WAL
I20260812 06:18:00.240871 23556 log_reader.cc:385] T 4c4bb87bd9a74ad39e349330c615f06e: removed 12 log segments from log reader
I20260812 06:18:00.240942 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000003 (ops 12-16)
I20260812 06:18:00.240995 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000004 (ops 17-21)
I20260812 06:18:00.241051 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000005 (ops 22-26)
I20260812 06:18:00.241092 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000006 (ops 27-31)
I20260812 06:18:00.241130 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000007 (ops 32-36)
I20260812 06:18:00.241166 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000008 (ops 37-41)
I20260812 06:18:00.241204 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000009 (ops 42-46)
I20260812 06:18:00.241245 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000010 (ops 47-51)
I20260812 06:18:00.241282 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000011 (ops 52-56)
I20260812 06:18:00.241318 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000012 (ops 57-60)
I20260812 06:18:00.241354 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000013 (ops 61-65)
I20260812 06:18:00.241391 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000014 (ops 66-70)
I20260812 06:18:00.271986 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: LogGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:00.272544 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e): 483 bytes on disk
I20260812 06:18:00.273027 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.273540 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=3.181125
I20260812 06:18:00.298727 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.025s	user 0.012s	sys 0.012s Metrics: {"bytes_written":5046218,"delete_count":0,"lbm_write_time_us":6362,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:18:00.299269 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.196750
I20260812 06:18:00.310060 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":3684,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:18:00.310804 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:00.541028 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.230s	user 0.149s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1344,"lbm_read_time_us":15263,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38767,"lbm_writes_lt_1ms":643,"mutex_wait_us":866,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:00.541635 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:00.608090 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.066s	user 0.026s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22491,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.608708 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:00.621217 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.622072 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:00.820461 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.198s	user 0.154s	sys 0.037s 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":162,"lbm_read_time_us":13679,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32212,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:18:00.821133 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:00.877619 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.056s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20011,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.878078 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:00.898875 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.021s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.899617 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:01.082551 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.183s	user 0.118s	sys 0.056s 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":252,"lbm_read_time_us":12578,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28928,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:01.083276 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:01.134720 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.051s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19916,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.135234 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:01.147497 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.148110 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:01.326237 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.178s	user 0.109s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":11611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29908,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:01.327068 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:01.375931 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21357,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.376436 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:01.389322 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.389936 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:01.556190 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.166s	user 0.122s	sys 0.032s 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":154,"lbm_read_time_us":10412,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30964,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:18:01.556926 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:01.609753 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.053s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23522,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.610373 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:01.621869 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.622390 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:01.792657 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.170s	user 0.123s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":983,"lbm_read_time_us":10848,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32960,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:18:01.793262 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:01.850342 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.057s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":22989,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.850871 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:01.861950 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.862452 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:01.894351 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":35,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1137,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1592,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":36736}
I20260812 06:18:01.895048 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling LogGCOp(4c4bb87bd9a74ad39e349330c615f06e): free 133477454 bytes of WAL
I20260812 06:18:01.895264 23556 log_reader.cc:385] T 4c4bb87bd9a74ad39e349330c615f06e: removed 13 log segments from log reader
I20260812 06:18:01.895323 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000015 (ops 71-75)
I20260812 06:18:01.895376 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000016 (ops 76-80)
I20260812 06:18:01.895431 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000017 (ops 81-85)
I20260812 06:18:01.895473 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000018 (ops 86-90)
I20260812 06:18:01.895509 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000019 (ops 91-95)
I20260812 06:18:01.895546 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000020 (ops 96-100)
I20260812 06:18:01.895583 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000021 (ops 101-105)
I20260812 06:18:01.895620 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000022 (ops 106-110)
I20260812 06:18:01.895656 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000023 (ops 111-115)
I20260812 06:18:01.895694 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000024 (ops 116-120)
I20260812 06:18:01.895730 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000025 (ops 121-125)
I20260812 06:18:01.895766 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000026 (ops 126-130)
I20260812 06:18:01.895802 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000027 (ops 131-135)
I20260812 06:18:01.926121 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: LogGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:01.926515 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e): 492 bytes on disk
I20260812 06:18:01.926946 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.927460 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=6.157687
I20260812 06:18:01.957039 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.029s	user 0.009s	sys 0.017s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":12414,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:01.957652 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:02.157783 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.200s	user 0.143s	sys 0.050s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979627,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":388,"lbm_read_time_us":12703,"lbm_reads_lt_1ms":765,"lbm_write_time_us":37139,"lbm_writes_lt_1ms":743,"mutex_wait_us":68,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:18:02.158537 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=18.063937
I20260812 06:18:02.230125 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.070s	user 0.034s	sys 0.036s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26969,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:02.231124 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:02.242610 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.243130 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:02.457161 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.214s	user 0.154s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":15868,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36416,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":3000}
I20260812 06:18:02.457894 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:02.526088 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.068s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23495,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.526770 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:02.538038 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.538529 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:02.736806 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.198s	user 0.129s	sys 0.056s 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":1146,"lbm_read_time_us":13732,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34657,"lbm_writes_lt_1ms":543,"mutex_wait_us":354,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:02.737756 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=14.095187
I20260812 06:18:02.810037 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.072s	user 0.035s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.810678 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:02.830278 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.019s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.831020 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:03.003628 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.172s	user 0.121s	sys 0.051s 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":597,"lbm_read_time_us":14913,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28004,"lbm_writes_lt_1ms":543,"mutex_wait_us":354,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:18:03.004334 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:18:03.039726 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.035s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17282,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.040251 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:03.059911 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.060424 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:03.196822 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.136s	user 0.111s	sys 0.024s 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":763,"lbm_read_time_us":7716,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29380,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:18:03.197500 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:18:03.245471 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.048s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16578,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.246093 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:03.258589 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.259182 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:03.382603 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.123s	user 0.102s	sys 0.021s 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":185,"lbm_read_time_us":9892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24345,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:18:03.383387 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=10.126437
I20260812 06:18:03.428090 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.045s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16504,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.428571 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:03.439409 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.439826 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:03.471719 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushMRSOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1169,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1873,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:03.472543 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling LogGCOp(4c4bb87bd9a74ad39e349330c615f06e): free 124710562 bytes of WAL
I20260812 06:18:03.472803 23556 log_reader.cc:385] T 4c4bb87bd9a74ad39e349330c615f06e: removed 12 log segments from log reader
I20260812 06:18:03.472867 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000028 (ops 136-140)
I20260812 06:18:03.472904 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000029 (ops 141-145)
I20260812 06:18:03.472934 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000030 (ops 146-150)
I20260812 06:18:03.472961 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000031 (ops 151-155)
I20260812 06:18:03.472987 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000032 (ops 156-160)
I20260812 06:18:03.473028 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000033 (ops 161-165)
I20260812 06:18:03.473052 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000034 (ops 166-170)
I20260812 06:18:03.473080 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000035 (ops 171-175)
I20260812 06:18:03.473109 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000036 (ops 176-180)
I20260812 06:18:03.473143 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000037 (ops 181-185)
I20260812 06:18:03.473177 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000038 (ops 186-190)
I20260812 06:18:03.473203 23556 log.cc:1079] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/4c4bb87bd9a74ad39e349330c615f06e/wal-000000039 (ops 191-195)
I20260812 06:18:03.506234 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: LogGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.033s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:18:03.506691 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:03.528337 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.528777 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e): 473 bytes on disk
I20260812 06:18:03.529157 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: UndoDeltaBlockGCOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.529714 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=2.188937
I20260812 06:18:03.539703 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: FlushDeltaMemStoresOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.540089 23655 maintenance_manager.cc:419] P be308f2c552841a3b20007bd759f6d88: Scheduling MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e): perf score=1.000000
I20260812 06:18:03.577003 23390 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.165s	user 1.892s	sys 0.144s
I20260812 06:18:03.656910 23390 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.001s	sys 0.000s
I20260812 06:18:03.657609 23390 tablet_server.cc:179] TabletServer@127.22.215.129:0 shutting down...
I20260812 06:18:03.703496 23556 maintenance_manager.cc:643] P be308f2c552841a3b20007bd759f6d88: MajorDeltaCompactionOp(4c4bb87bd9a74ad39e349330c615f06e) complete. Timing: real 0.163s	user 0.122s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1162,"lbm_read_time_us":13687,"lbm_reads_lt_1ms":670,"lbm_write_time_us":27901,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8832,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:18:03.704407 23390 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:03.704973 23390 tablet_replica.cc:333] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88: stopping tablet replica
I20260812 06:18:03.705367 23390 raft_consensus.cc:2243] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.705760 23390 raft_consensus.cc:2272] T 4c4bb87bd9a74ad39e349330c615f06e P be308f2c552841a3b20007bd759f6d88 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.723619 23390 tablet_server.cc:196] TabletServer@127.22.215.129:0 shutdown complete.
I20260812 06:18:03.757128 23390 master.cc:562] Master@127.22.215.190:43515 shutting down...
I20260812 06:18:03.762364 23390 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.762580 23390 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.762643 23390 tablet_replica.cc:333] T 00000000000000000000000000000000 P b987b4c99da745b69ff96892de384e2f: stopping tablet replica
I20260812 06:18:03.775964 23390 master.cc:584] Master@127.22.215.190:43515 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5777 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:03.876596 23390 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.215.190:44073
I20260812 06:18:03.876979 23390 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.880162 23711 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.880360 23707 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:03.880402 23390 server_base.cc:1061] running on GCE node
W20260812 06:18:03.880854 23708 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:03.881124 23390 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.881170 23390 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:03.881186 23390 hybrid_clock.cc:648] HybridClock initialized: now 1786515483881186 us; error 0 us; skew 500 ppm
I20260812 06:18:03.882261 23390 webserver.cc:533] Webserver started at http://127.22.215.190:33475/ using document root <none> and password file <none>
I20260812 06:18:03.882467 23390 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.882521 23390 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.882577 23390 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.882961 23390 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/master-0-root/instance:
uuid: "e6e8438a47e44f1792e7aac697bf874d"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-zr1t"
I20260812 06:18:03.884670 23390 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:03.885867 23719 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:03.886173 23390 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.886245 23390 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/master-0-root
uuid: "e6e8438a47e44f1792e7aac697bf874d"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-zr1t"
I20260812 06:18:03.886355 23390 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-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:03.921104 23390 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.921622 23390 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.925976 23390 rpc_server.cc:307] RPC server started. Bound to: 127.22.215.190:44073
I20260812 06:18:03.929167 23797 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.215.190:44073 every 8 connection(s)
I20260812 06:18:03.929936 23798 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:03.939924 23798 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d: Bootstrap starting.
I20260812 06:18:03.940954 23798 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.942355 23798 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d: No bootstrap required, opened a new log
I20260812 06:18:03.942914 23798 raft_consensus.cc:359] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6e8438a47e44f1792e7aac697bf874d" member_type: VOTER }
I20260812 06:18:03.943018 23798 raft_consensus.cc:385] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.943042 23798 raft_consensus.cc:740] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e6e8438a47e44f1792e7aac697bf874d, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.943207 23798 consensus_queue.cc:260] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [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: "e6e8438a47e44f1792e7aac697bf874d" member_type: VOTER }
I20260812 06:18:03.943286 23798 raft_consensus.cc:399] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.943310 23798 raft_consensus.cc:493] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.943361 23798 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.944223 23798 raft_consensus.cc:515] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6e8438a47e44f1792e7aac697bf874d" member_type: VOTER }
I20260812 06:18:03.944392 23798 leader_election.cc:304] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [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: e6e8438a47e44f1792e7aac697bf874d; no voters: 
I20260812 06:18:03.944669 23798 leader_election.cc:290] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.944877 23801 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.945091 23801 raft_consensus.cc:697] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 1 LEADER]: Becoming Leader. State: Replica: e6e8438a47e44f1792e7aac697bf874d, State: Running, Role: LEADER
I20260812 06:18:03.945250 23801 consensus_queue.cc:237] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [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: "e6e8438a47e44f1792e7aac697bf874d" member_type: VOTER }
I20260812 06:18:03.945387 23798 sys_catalog.cc:565] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:03.945855 23805 sys_catalog.cc:455] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [sys.catalog]: SysCatalogTable state changed. Reason: New leader e6e8438a47e44f1792e7aac697bf874d. Latest consensus state: current_term: 1 leader_uuid: "e6e8438a47e44f1792e7aac697bf874d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6e8438a47e44f1792e7aac697bf874d" member_type: VOTER } }
I20260812 06:18:03.945959 23805 sys_catalog.cc:458] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.945832 23804 sys_catalog.cc:455] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e6e8438a47e44f1792e7aac697bf874d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6e8438a47e44f1792e7aac697bf874d" member_type: VOTER } }
I20260812 06:18:03.946053 23804 sys_catalog.cc:458] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.946357 23808 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:03.947273 23808 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:03.948038 23390 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:03.950138 23808 catalog_manager.cc:1383] Generated new cluster ID: 78f22868db264b668b5c0168f7a06648
I20260812 06:18:03.950214 23808 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:03.981191 23808 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:03.981941 23808 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:03.986954 23808 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d: Generated new TSK 0
I20260812 06:18:03.987210 23808 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:04.013140 23390 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:04.015631 23830 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:04.015610 23832 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:04.015793 23829 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:04.015727 23390 server_base.cc:1061] running on GCE node
I20260812 06:18:04.016207 23390 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:04.016266 23390 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:04.016285 23390 hybrid_clock.cc:648] HybridClock initialized: now 1786515484016285 us; error 0 us; skew 500 ppm
I20260812 06:18:04.017292 23390 webserver.cc:533] Webserver started at http://127.22.215.129:42631/ using document root <none> and password file <none>
I20260812 06:18:04.017458 23390 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:04.017573 23390 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:04.017663 23390 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:04.018147 23390 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/instance:
uuid: "ae89c91e806a4864b4c7c15e753822bf"
format_stamp: "Formatted at 2026-08-12 06:18:04 on dist-test-slave-zr1t"
I20260812 06:18:04.019954 23390 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:04.021150 23839 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:04.021597 23390 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:04.021703 23390 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root
uuid: "ae89c91e806a4864b4c7c15e753822bf"
format_stamp: "Formatted at 2026-08-12 06:18:04 on dist-test-slave-zr1t"
I20260812 06:18:04.021798 23390 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-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:04.037045 23390 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:04.037595 23390 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:04.037983 23390 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:04.038555 23390 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:04.038623 23390 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:04.038694 23390 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:04.038745 23390 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:04.043949 23390 rpc_server.cc:307] RPC server started. Bound to: 127.22.215.129:43751
I20260812 06:18:04.044516 23942 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.215.129:43751 every 8 connection(s)
I20260812 06:18:04.055183 23943 heartbeater.cc:344] Connected to a master server at 127.22.215.190:44073
I20260812 06:18:04.055404 23943 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:04.055907 23943 heartbeater.cc:507] Master 127.22.215.190:44073 requested a full tablet report, sending...
I20260812 06:18:04.057130 23738 ts_manager.cc:194] Registered new tserver with Master: ae89c91e806a4864b4c7c15e753822bf (127.22.215.129:43751)
I20260812 06:18:04.057284 23390 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012588589s
I20260812 06:18:04.058109 23738 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55536
I20260812 06:18:04.067348 23738 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55544:
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:04.078872 23887 tablet_service.cc:1511] Processing CreateTablet for tablet 1d3dd6e55329474ba77feda14f066e40 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c53965bb0c3f4d6680460173a3a4eb49]), partition=
I20260812 06:18:04.079167 23887 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1d3dd6e55329474ba77feda14f066e40. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:04.081261 23961 tablet_bootstrap.cc:492] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Bootstrap starting.
I20260812 06:18:04.082332 23961 tablet_bootstrap.cc:654] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:04.083757 23961 tablet_bootstrap.cc:492] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: No bootstrap required, opened a new log
I20260812 06:18:04.083884 23961 ts_tablet_manager.cc:1403] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:04.084477 23961 raft_consensus.cc:359] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae89c91e806a4864b4c7c15e753822bf" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 43751 } }
I20260812 06:18:04.084594 23961 raft_consensus.cc:385] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:04.084642 23961 raft_consensus.cc:740] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae89c91e806a4864b4c7c15e753822bf, State: Initialized, Role: FOLLOWER
I20260812 06:18:04.084790 23961 consensus_queue.cc:260] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [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: "ae89c91e806a4864b4c7c15e753822bf" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 43751 } }
I20260812 06:18:04.084897 23961 raft_consensus.cc:399] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:04.084946 23961 raft_consensus.cc:493] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:04.085000 23961 raft_consensus.cc:3060] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:04.085958 23961 raft_consensus.cc:515] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae89c91e806a4864b4c7c15e753822bf" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 43751 } }
I20260812 06:18:04.086136 23961 leader_election.cc:304] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [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: ae89c91e806a4864b4c7c15e753822bf; no voters: 
I20260812 06:18:04.086374 23961 leader_election.cc:290] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:04.086551 23965 raft_consensus.cc:2804] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:04.086822 23965 raft_consensus.cc:697] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 1 LEADER]: Becoming Leader. State: Replica: ae89c91e806a4864b4c7c15e753822bf, State: Running, Role: LEADER
I20260812 06:18:04.086884 23961 ts_tablet_manager.cc:1434] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:04.086926 23943 heartbeater.cc:499] Master 127.22.215.190:44073 was elected leader, sending a full tablet report...
I20260812 06:18:04.086987 23965 consensus_queue.cc:237] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [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: "ae89c91e806a4864b4c7c15e753822bf" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 43751 } }
I20260812 06:18:04.088758 23738 catalog_manager.cc:5719] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf reported cstate change: term changed from 0 to 1, leader changed from <none> to ae89c91e806a4864b4c7c15e753822bf (127.22.215.129). New cstate: current_term: 1 leader_uuid: "ae89c91e806a4864b4c7c15e753822bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae89c91e806a4864b4c7c15e753822bf" member_type: VOTER last_known_addr { host: "127.22.215.129" port: 43751 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:04.152448 23390 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.015s	sys 0.008s
I20260812 06:18:04.295369 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushMRSOp(1d3dd6e55329474ba77feda14f066e40): perf score=15.086190
I20260812 06:18:04.459656 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushMRSOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.164s	user 0.101s	sys 0.060s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1269,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42869,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:18:04.460407 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling LogGCOp(1d3dd6e55329474ba77feda14f066e40): free 20290830 bytes of WAL
I20260812 06:18:04.460646 23850 log_reader.cc:385] T 1d3dd6e55329474ba77feda14f066e40: removed 2 log segments from log reader
I20260812 06:18:04.460691 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000001 (ops 1-6)
I20260812 06:18:04.460721 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000002 (ops 7-10)
I20260812 06:18:04.466060 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: LogGCOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:04.466564 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40): 12308959 bytes on disk
I20260812 06:18:04.467794 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":130,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.468418 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:04.485376 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.486102 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:04.655210 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.169s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":323,"lbm_read_time_us":9769,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31759,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"thread_start_us":336,"threads_started":5,"update_count":2000}
I20260812 06:18:04.656052 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=11.118625
I20260812 06:18:04.705941 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.050s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18458,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:04.706688 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:04.721273 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.014s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4474,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.721903 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:04.893741 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.172s	user 0.128s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":789,"lbm_read_time_us":12374,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26526,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:18:04.894467 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=11.118625
I20260812 06:18:04.941250 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.047s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19672,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:04.941811 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:04.953711 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":500}
I20260812 06:18:04.954187 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:04.963829 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3618,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.964319 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:05.157415 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.193s	user 0.133s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":325,"lbm_read_time_us":11451,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34005,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:18:05.158231 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:05.210713 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.052s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18500,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.211315 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:05.226625 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5623,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.227229 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:05.384848 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.157s	user 0.116s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":10402,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31942,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:18:05.385629 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=10.126437
I20260812 06:18:05.417146 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.031s	user 0.008s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13963,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.417778 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:05.433089 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.433646 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:05.567631 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.134s	user 0.100s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":9855,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23653,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:05.568607 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=10.126437
I20260812 06:18:05.611763 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.043s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19784,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.612282 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:05.622759 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.623565 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:05.750378 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.127s	user 0.103s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":351,"lbm_read_time_us":10199,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22908,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2000}
I20260812 06:18:05.751092 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=10.126437
I20260812 06:18:05.808899 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.058s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18006,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.809738 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:05.827066 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.827638 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushMRSOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:05.874490 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushMRSOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.047s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1267,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2326,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:05.875286 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling LogGCOp(1d3dd6e55329474ba77feda14f066e40): free 121006430 bytes of WAL
I20260812 06:18:05.875548 23850 log_reader.cc:385] T 1d3dd6e55329474ba77feda14f066e40: removed 12 log segments from log reader
I20260812 06:18:05.875623 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000003 (ops 11-15)
I20260812 06:18:05.875677 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000004 (ops 16-20)
I20260812 06:18:05.875731 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000005 (ops 21-25)
I20260812 06:18:05.875773 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000006 (ops 26-30)
I20260812 06:18:05.875813 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000007 (ops 31-35)
I20260812 06:18:05.875852 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000008 (ops 36-40)
I20260812 06:18:05.875892 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000009 (ops 41-45)
I20260812 06:18:05.875931 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000010 (ops 46-50)
I20260812 06:18:05.875972 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000011 (ops 51-54)
I20260812 06:18:05.876037 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000012 (ops 55-59)
I20260812 06:18:05.876093 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000013 (ops 60-64)
I20260812 06:18:05.876135 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000014 (ops 65-69)
I20260812 06:18:05.903923 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: LogGCOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:05.904465 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40): 472 bytes on disk
I20260812 06:18:05.905031 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40) 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:18:05.905679 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:05.927887 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.022s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.928409 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:05.938885 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.939342 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:06.136547 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.197s	user 0.141s	sys 0.055s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":670,"lbm_read_time_us":14386,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31468,"lbm_writes_lt_1ms":643,"mutex_wait_us":332,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":74112,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:06.137275 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:06.187240 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.050s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20454,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.187800 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:06.200695 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4586,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.201295 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:06.404457 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.203s	user 0.125s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":796,"lbm_read_time_us":17011,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31001,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:18:06.405095 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:06.465826 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.061s	user 0.041s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20480,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.466362 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:06.483702 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6699,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.484406 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:06.666149 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.181s	user 0.115s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":13398,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28220,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:06.666769 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:06.729271 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.062s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.729969 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:06.740623 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.741057 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:06.925678 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.184s	user 0.126s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":618,"lbm_read_time_us":12673,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29720,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:18:06.926365 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:06.975162 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.049s	user 0.015s	sys 0.026s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18652,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.975690 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:06.997128 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.021s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.997749 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:07.190943 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.193s	user 0.110s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":14653,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30276,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2500}
I20260812 06:18:07.191517 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:07.241895 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.050s	user 0.026s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17539,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.242362 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:07.254004 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.254442 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:07.452335 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.198s	user 0.147s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":616,"lbm_read_time_us":11970,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30987,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:18:07.452992 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:07.504741 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.052s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22295,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.505265 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:07.515602 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.516052 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushMRSOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:07.550355 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushMRSOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.034s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1383,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2252,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:07.551087 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling LogGCOp(1d3dd6e55329474ba77feda14f066e40): free 128414172 bytes of WAL
I20260812 06:18:07.551311 23850 log_reader.cc:385] T 1d3dd6e55329474ba77feda14f066e40: removed 12 log segments from log reader
I20260812 06:18:07.551354 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000015 (ops 70-74)
I20260812 06:18:07.551402 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000016 (ops 75-79)
I20260812 06:18:07.551445 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000017 (ops 80-85)
I20260812 06:18:07.551487 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000018 (ops 86-90)
I20260812 06:18:07.551533 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000019 (ops 91-95)
I20260812 06:18:07.551592 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000020 (ops 96-100)
I20260812 06:18:07.551631 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000021 (ops 101-105)
I20260812 06:18:07.551671 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000022 (ops 106-110)
I20260812 06:18:07.551714 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000023 (ops 111-115)
I20260812 06:18:07.551754 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000024 (ops 116-120)
I20260812 06:18:07.551793 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000025 (ops 121-125)
I20260812 06:18:07.551832 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000026 (ops 126-130)
I20260812 06:18:07.582080 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: LogGCOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:07.582581 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40): 493 bytes on disk
I20260812 06:18:07.583133 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:07.583726 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:07.600636 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.017s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.601130 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:07.611687 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.612104 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:07.853964 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.242s	user 0.160s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938785,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":686,"lbm_read_time_us":16604,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39891,"lbm_writes_lt_1ms":743,"mutex_wait_us":46,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:07.855305 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=16.079562
I20260812 06:18:07.931614 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.076s	user 0.046s	sys 0.016s Metrics: {"bytes_written":17722676,"delete_count":0,"lbm_write_time_us":28884,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:18:07.932109 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=5.165500
I20260812 06:18:07.959511 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.027s	user 0.016s	sys 0.003s Metrics: {"bytes_written":6892312,"delete_count":0,"lbm_write_time_us":8620,"lbm_writes_lt_1ms":171,"reinsert_count":0,"update_count":840}
I20260812 06:18:07.960029 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:08.195886 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.236s	user 0.156s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836145,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":14641,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37039,"lbm_writes_lt_1ms":643,"mutex_wait_us":72,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":3000}
I20260812 06:18:08.196592 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=18.063937
I20260812 06:18:08.272548 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.076s	user 0.047s	sys 0.019s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":31344,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:08.273128 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:08.285902 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.286373 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:08.509877 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.223s	user 0.146s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836140,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1068,"lbm_read_time_us":14662,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39988,"lbm_writes_lt_1ms":643,"mutex_wait_us":372,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":3000}
I20260812 06:18:08.510735 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=18.063937
I20260812 06:18:08.580672 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.070s	user 0.037s	sys 0.017s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26190,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:08.581152 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:08.594219 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.594750 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:08.807960 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.213s	user 0.129s	sys 0.084s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836140,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":15388,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36738,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:18:08.808569 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:08.866238 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.057s	user 0.041s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.866744 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:08.878545 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.879222 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:09.072386 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.193s	user 0.117s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":14497,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33483,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24064,"update_count":2500}
I20260812 06:18:09.072970 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=14.095187
I20260812 06:18:09.135721 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.063s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20946,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.136222 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:09.146765 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4224,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.147265 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushMRSOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:09.191097 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushMRSOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.044s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1302,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1517,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:09.191898 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling LogGCOp(1d3dd6e55329474ba77feda14f066e40): free 128867727 bytes of WAL
I20260812 06:18:09.192148 23850 log_reader.cc:385] T 1d3dd6e55329474ba77feda14f066e40: removed 13 log segments from log reader
I20260812 06:18:09.192217 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000027 (ops 131-135)
I20260812 06:18:09.192272 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000028 (ops 136-140)
I20260812 06:18:09.192328 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000029 (ops 141-145)
I20260812 06:18:09.192371 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000030 (ops 146-150)
I20260812 06:18:09.192409 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000031 (ops 151-154)
I20260812 06:18:09.192448 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000032 (ops 155-159)
I20260812 06:18:09.192494 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000033 (ops 160-164)
I20260812 06:18:09.192535 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000034 (ops 165-168)
I20260812 06:18:09.192574 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000035 (ops 169-173)
I20260812 06:18:09.192615 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000036 (ops 174-178)
I20260812 06:18:09.192654 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000037 (ops 179-183)
I20260812 06:18:09.192694 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000038 (ops 184-188)
I20260812 06:18:09.192734 23850 log.cc:1079] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: Deleting log segment in path: /tmp/dist-test-task72IEOT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515478088009-23390-0/minicluster-data/ts-0-root/wals/1d3dd6e55329474ba77feda14f066e40/wal-000000039 (ops 189-192)
I20260812 06:18:09.222256 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: LogGCOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:09.222652 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40): 472 bytes on disk
I20260812 06:18:09.223140 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: UndoDeltaBlockGCOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.223672 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=3.181125
I20260812 06:18:09.238125 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4313,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:09.238579 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=2.188937
I20260812 06:18:09.252055 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5155,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.252537 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40): perf score=1.000000
I20260812 06:18:09.393826 23390 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.241s	user 1.888s	sys 0.248s
I20260812 06:18:09.466007 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: MajorDeltaCompactionOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.213s	user 0.140s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938775,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":744,"lbm_read_time_us":16956,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36356,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":34688,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:09.466804 23944 maintenance_manager.cc:419] P ae89c91e806a4864b4c7c15e753822bf: Scheduling FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40): perf score=10.126437
I20260812 06:18:09.482398 23390 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.088s	user 0.006s	sys 0.000s
I20260812 06:18:09.483095 23390 tablet_server.cc:179] TabletServer@127.22.215.129:0 shutting down...
I20260812 06:18:09.504387 23850 maintenance_manager.cc:643] P ae89c91e806a4864b4c7c15e753822bf: FlushDeltaMemStoresOp(1d3dd6e55329474ba77feda14f066e40) complete. Timing: real 0.036s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15797,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.504910 23390 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:09.505151 23390 tablet_replica.cc:333] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf: stopping tablet replica
I20260812 06:18:09.505309 23390 raft_consensus.cc:2243] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:09.505482 23390 raft_consensus.cc:2272] T 1d3dd6e55329474ba77feda14f066e40 P ae89c91e806a4864b4c7c15e753822bf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:09.508703 23390 tablet_server.cc:196] TabletServer@127.22.215.129:0 shutdown complete.
I20260812 06:18:09.524070 23390 master.cc:562] Master@127.22.215.190:44073 shutting down...
I20260812 06:18:09.527704 23390 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:09.527891 23390 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:09.527976 23390 tablet_replica.cc:333] T 00000000000000000000000000000000 P e6e8438a47e44f1792e7aac697bf874d: stopping tablet replica
I20260812 06:18:09.540396 23390 master.cc:584] Master@127.22.215.190:44073 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5753 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11532 ms total)

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