[==========] 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:54.633725 19299 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.216.254:35809
I20260812 06:17:54.634862 19299 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:54.635512 19299 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:54.642875 19306 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:54.642973 19304 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:54.643133 19299 server_base.cc:1061] running on GCE node
W20260812 06:17:54.643157 19308 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:54.643733 19299 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:54.643865 19299 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:54.643935 19299 hybrid_clock.cc:648] HybridClock initialized: now 1786515474643932 us; error 0 us; skew 500 ppm
I20260812 06:17:54.645907 19299 webserver.cc:533] Webserver started at http://127.18.216.254:41733/ using document root <none> and password file <none>
I20260812 06:17:54.646687 19299 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:54.646781 19299 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:54.647055 19299 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:54.648823 19299 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/master-0-root/instance:
uuid: "3734dadf6cbf4265bef44b0e81b5cfb2"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-tm1g"
I20260812 06:17:54.652616 19299 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.004s
I20260812 06:17:54.655092 19314 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:54.656225 19299 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:54.656451 19299 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/master-0-root
uuid: "3734dadf6cbf4265bef44b0e81b5cfb2"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-tm1g"
I20260812 06:17:54.656587 19299 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-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:54.684461 19299 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:54.685226 19299 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:54.685446 19299 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:54.693794 19370 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.216.254:35809 every 8 connection(s)
I20260812 06:17:54.693794 19299 rpc_server.cc:307] RPC server started. Bound to: 127.18.216.254:35809
I20260812 06:17:54.696233 19371 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:54.701920 19371 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2: Bootstrap starting.
I20260812 06:17:54.704512 19371 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:54.705474 19371 log.cc:826] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:54.707394 19371 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2: No bootstrap required, opened a new log
I20260812 06:17:54.710253 19371 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3734dadf6cbf4265bef44b0e81b5cfb2" member_type: VOTER }
I20260812 06:17:54.710443 19371 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:54.710496 19371 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3734dadf6cbf4265bef44b0e81b5cfb2, State: Initialized, Role: FOLLOWER
I20260812 06:17:54.711126 19371 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [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: "3734dadf6cbf4265bef44b0e81b5cfb2" member_type: VOTER }
I20260812 06:17:54.711274 19371 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:54.711316 19371 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:54.711407 19371 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:54.712203 19371 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3734dadf6cbf4265bef44b0e81b5cfb2" member_type: VOTER }
I20260812 06:17:54.712603 19371 leader_election.cc:304] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [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: 3734dadf6cbf4265bef44b0e81b5cfb2; no voters: 
I20260812 06:17:54.712886 19371 leader_election.cc:290] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:54.713069 19375 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:54.713326 19375 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 1 LEADER]: Becoming Leader. State: Replica: 3734dadf6cbf4265bef44b0e81b5cfb2, State: Running, Role: LEADER
I20260812 06:17:54.713758 19375 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [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: "3734dadf6cbf4265bef44b0e81b5cfb2" member_type: VOTER }
I20260812 06:17:54.713974 19371 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:54.715770 19377 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3734dadf6cbf4265bef44b0e81b5cfb2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3734dadf6cbf4265bef44b0e81b5cfb2" member_type: VOTER } }
I20260812 06:17:54.716027 19377 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:54.715794 19378 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3734dadf6cbf4265bef44b0e81b5cfb2. Latest consensus state: current_term: 1 leader_uuid: "3734dadf6cbf4265bef44b0e81b5cfb2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3734dadf6cbf4265bef44b0e81b5cfb2" member_type: VOTER } }
I20260812 06:17:54.716246 19299 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:54.716264 19378 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [sys.catalog]: This master's current role is: LEADER
W20260812 06:17:54.718688 19392 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:54.718771 19392 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:54.718843 19393 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:54.719743 19393 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:54.724871 19393 catalog_manager.cc:1383] Generated new cluster ID: cbb6352bd24d456097fc149536d54570
I20260812 06:17:54.724972 19393 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:54.736012 19393 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:54.736963 19393 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:54.743386 19393 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2: Generated new TSK 0
I20260812 06:17:54.744065 19393 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:54.748749 19299 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:54.751446 19400 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:54.751612 19401 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:54.751709 19403 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:54.751715 19299 server_base.cc:1061] running on GCE node
I20260812 06:17:54.752027 19299 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:54.752082 19299 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:54.752104 19299 hybrid_clock.cc:648] HybridClock initialized: now 1786515474752104 us; error 0 us; skew 500 ppm
I20260812 06:17:54.753042 19299 webserver.cc:533] Webserver started at http://127.18.216.193:41071/ using document root <none> and password file <none>
I20260812 06:17:54.753211 19299 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:54.753271 19299 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:54.753348 19299 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:54.753779 19299 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/instance:
uuid: "689f77e56a1945668b6cc606360ed586"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-tm1g"
I20260812 06:17:54.755724 19299 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:54.756984 19408 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:54.757314 19299 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:54.757380 19299 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root
uuid: "689f77e56a1945668b6cc606360ed586"
format_stamp: "Formatted at 2026-08-12 06:17:54 on dist-test-slave-tm1g"
I20260812 06:17:54.757468 19299 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-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:54.774876 19299 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:54.775398 19299 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:54.775893 19299 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:54.776783 19299 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:54.776861 19299 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.776949 19299 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:54.776995 19299 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:54.783867 19299 rpc_server.cc:307] RPC server started. Bound to: 127.18.216.193:41831
I20260812 06:17:54.783913 19487 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.216.193:41831 every 8 connection(s)
I20260812 06:17:54.795907 19488 heartbeater.cc:344] Connected to a master server at 127.18.216.254:35809
I20260812 06:17:54.796200 19488 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:54.796733 19488 heartbeater.cc:507] Master 127.18.216.254:35809 requested a full tablet report, sending...
I20260812 06:17:54.798547 19333 ts_manager.cc:194] Registered new tserver with Master: 689f77e56a1945668b6cc606360ed586 (127.18.216.193:41831)
I20260812 06:17:54.798668 19299 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014130604s
I20260812 06:17:54.800172 19333 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33684
I20260812 06:17:54.810047 19333 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33694:
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:54.826618 19445 tablet_service.cc:1511] Processing CreateTablet for tablet f2dafcd29fb44ac991ee153ade3d0e87 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6c9eacf4b3f04d73b12faa3d73c5b1b2]), partition=
I20260812 06:17:54.827167 19445 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f2dafcd29fb44ac991ee153ade3d0e87. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:54.830019 19502 tablet_bootstrap.cc:492] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Bootstrap starting.
I20260812 06:17:54.831043 19502 tablet_bootstrap.cc:654] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:54.832321 19502 tablet_bootstrap.cc:492] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: No bootstrap required, opened a new log
I20260812 06:17:54.832463 19502 ts_tablet_manager.cc:1403] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:54.833061 19502 raft_consensus.cc:359] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "689f77e56a1945668b6cc606360ed586" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 41831 } }
I20260812 06:17:54.833194 19502 raft_consensus.cc:385] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:54.833246 19502 raft_consensus.cc:740] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 689f77e56a1945668b6cc606360ed586, State: Initialized, Role: FOLLOWER
I20260812 06:17:54.833432 19502 consensus_queue.cc:260] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [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: "689f77e56a1945668b6cc606360ed586" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 41831 } }
I20260812 06:17:54.833560 19502 raft_consensus.cc:399] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:54.833616 19502 raft_consensus.cc:493] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:54.833678 19502 raft_consensus.cc:3060] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:54.834497 19502 raft_consensus.cc:515] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "689f77e56a1945668b6cc606360ed586" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 41831 } }
I20260812 06:17:54.834669 19502 leader_election.cc:304] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [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: 689f77e56a1945668b6cc606360ed586; no voters: 
I20260812 06:17:54.834918 19502 leader_election.cc:290] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:54.835032 19504 raft_consensus.cc:2804] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:54.835354 19502 ts_tablet_manager.cc:1434] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:54.835637 19488 heartbeater.cc:499] Master 127.18.216.254:35809 was elected leader, sending a full tablet report...
I20260812 06:17:54.835264 19504 raft_consensus.cc:697] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 1 LEADER]: Becoming Leader. State: Replica: 689f77e56a1945668b6cc606360ed586, State: Running, Role: LEADER
I20260812 06:17:54.835856 19504 consensus_queue.cc:237] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [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: "689f77e56a1945668b6cc606360ed586" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 41831 } }
I20260812 06:17:54.838927 19333 catalog_manager.cc:5719] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 reported cstate change: term changed from 0 to 1, leader changed from <none> to 689f77e56a1945668b6cc606360ed586 (127.18.216.193). New cstate: current_term: 1 leader_uuid: "689f77e56a1945668b6cc606360ed586" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "689f77e56a1945668b6cc606360ed586" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 41831 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:54.913344 19299 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.067s	user 0.020s	sys 0.012s
I20260812 06:17:55.035184 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=15.086190
I20260812 06:17:55.205231 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.170s	user 0.117s	sys 0.048s Metrics: {"bytes_written":12717736,"cfile_init":1,"compiler_manager_pool.queue_time_us":326,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":915,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40516,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":287104,"thread_start_us":151,"threads_started":1,"update_count":1550}
I20260812 06:17:55.206634 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87): free 8725963 bytes of WAL
I20260812 06:17:55.206951 19415 log_reader.cc:385] T f2dafcd29fb44ac991ee153ade3d0e87: removed 1 log segments from log reader
I20260812 06:17:55.207039 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000001 (ops 1-6)
I20260812 06:17:55.209430 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:55.209725 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:55.224095 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.224529 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87): 12308955 bytes on disk
I20260812 06:17:55.225100 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87) 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:17:55.225531 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:55.239567 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4950,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.240414 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:55.419183 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.179s	user 0.150s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":64,"lbm_read_time_us":10767,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31874,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":232,"threads_started":5,"update_count":2500}
I20260812 06:17:55.419768 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=10.126437
I20260812 06:17:55.466704 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.047s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18875,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:55.467401 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:55.492202 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.492690 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:55.503775 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.504273 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:55.666556 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.162s	user 0.126s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":999,"lbm_read_time_us":11126,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31605,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:17:55.667197 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=14.095187
I20260812 06:17:55.720021 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.053s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20481,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.720494 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:55.731675 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4040,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.732152 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:55.902026 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.170s	user 0.143s	sys 0.013s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":12635,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31429,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":63872,"update_count":2500}
I20260812 06:17:55.902675 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=14.095187
I20260812 06:17:55.955116 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.052s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25829,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.955629 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:55.976933 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.021s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.977466 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:56.117808 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.140s	user 0.107s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":808,"lbm_read_time_us":9162,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28151,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:56.118291 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=14.095187
I20260812 06:17:56.163103 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.045s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18234,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.163677 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:56.174378 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.175027 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:56.339545 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.164s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1291,"lbm_read_time_us":11465,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31364,"lbm_writes_lt_1ms":543,"mutex_wait_us":343,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:56.341566 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=13.103000
I20260812 06:17:56.388980 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.047s	user 0.023s	sys 0.020s Metrics: {"bytes_written":14645857,"delete_count":0,"lbm_write_time_us":20367,"lbm_writes_lt_1ms":360,"reinsert_count":0,"update_count":1785}
I20260812 06:17:56.389499 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.196750
I20260812 06:17:56.413666 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.024s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2174483,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:17:56.414158 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:56.424229 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3661,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.424748 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:56.458240 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1593,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1481,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:56.459249 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87): free 132571311 bytes of WAL
I20260812 06:17:56.459513 19415 log_reader.cc:385] T f2dafcd29fb44ac991ee153ade3d0e87: removed 13 log segments from log reader
I20260812 06:17:56.459597 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000002 (ops 7-11)
I20260812 06:17:56.459657 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000003 (ops 12-16)
I20260812 06:17:56.459697 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000004 (ops 17-20)
I20260812 06:17:56.459734 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000005 (ops 21-25)
I20260812 06:17:56.459772 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000006 (ops 26-30)
I20260812 06:17:56.459810 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000007 (ops 31-35)
I20260812 06:17:56.459846 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000008 (ops 36-40)
I20260812 06:17:56.459882 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000009 (ops 41-45)
I20260812 06:17:56.459919 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000010 (ops 46-50)
I20260812 06:17:56.459955 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000011 (ops 51-55)
I20260812 06:17:56.459992 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000012 (ops 56-60)
I20260812 06:17:56.460029 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000013 (ops 61-64)
I20260812 06:17:56.460065 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000014 (ops 65-69)
I20260812 06:17:56.491933 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:56.492506 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87): 472 bytes on disk
I20260812 06:17:56.493088 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:56.493969 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=3.181125
I20260812 06:17:56.514094 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7105,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:56.514544 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:56.524575 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.525048 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:56.741724 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.216s	user 0.146s	sys 0.066s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938831,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":801,"lbm_read_time_us":15775,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39320,"lbm_writes_lt_1ms":743,"mutex_wait_us":305,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":94,"threads_started":1,"update_count":3500}
I20260812 06:17:56.742372 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=15.087375
I20260812 06:17:56.794523 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.052s	user 0.035s	sys 0.017s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23407,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:56.795351 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:56.815707 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.020s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.816265 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:56.826861 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.827353 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:57.003278 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.176s	user 0.120s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836241,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":724,"lbm_read_time_us":14467,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35204,"lbm_writes_lt_1ms":643,"mutex_wait_us":88,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3000}
I20260812 06:17:57.004061 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=14.095187
I20260812 06:17:57.055163 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.051s	user 0.015s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22914,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.055815 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:57.072139 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.072759 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:57.231839 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.159s	user 0.124s	sys 0.032s 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":613,"lbm_read_time_us":10691,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31792,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:57.232477 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=14.095187
I20260812 06:17:57.285638 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.053s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19804,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.286161 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:57.298136 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.298741 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:57.480865 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.182s	user 0.147s	sys 0.024s 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":924,"lbm_read_time_us":11398,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34288,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:57.481573 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=14.095187
I20260812 06:17:57.553036 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.071s	user 0.029s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30411,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.553563 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:57.564836 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4185,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.565385 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:57.770586 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.205s	user 0.125s	sys 0.063s 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":1240,"lbm_read_time_us":13146,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35134,"lbm_writes_lt_1ms":543,"mutex_wait_us":365,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":44800,"update_count":2500}
I20260812 06:17:57.771991 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=10.126437
I20260812 06:17:57.843667 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.071s	user 0.042s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21860,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.844763 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:57.865164 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.865904 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:58.108227 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.242s	user 0.166s	sys 0.062s 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":1133,"lbm_read_time_us":17217,"lbm_reads_lt_1ms":472,"lbm_write_time_us":36569,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":209,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:58.109094 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=18.063937
I20260812 06:17:58.166214 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.057s	user 0.040s	sys 0.013s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":26095,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:58.166886 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:58.186960 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.187865 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:58.226588 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.039s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1398560,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1780,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1775,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":34}
I20260812 06:17:58.227288 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87): free 132571329 bytes of WAL
I20260812 06:17:58.227523 19415 log_reader.cc:385] T f2dafcd29fb44ac991ee153ade3d0e87: removed 13 log segments from log reader
I20260812 06:17:58.227566 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000015 (ops 70-74)
I20260812 06:17:58.227596 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000016 (ops 75-79)
I20260812 06:17:58.227658 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000017 (ops 80-84)
I20260812 06:17:58.227703 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000018 (ops 85-88)
I20260812 06:17:58.227746 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000019 (ops 89-93)
I20260812 06:17:58.227806 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000020 (ops 94-98)
I20260812 06:17:58.227844 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000021 (ops 99-103)
I20260812 06:17:58.227882 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000022 (ops 104-108)
I20260812 06:17:58.227921 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000023 (ops 109-112)
I20260812 06:17:58.227958 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000024 (ops 113-117)
I20260812 06:17:58.227995 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000025 (ops 118-122)
I20260812 06:17:58.228034 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000026 (ops 123-127)
I20260812 06:17:58.228072 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000027 (ops 128-132)
I20260812 06:17:58.258654 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.031s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:58.259162 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87): 517 bytes on disk
I20260812 06:17:58.259788 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.260708 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=3.181125
I20260812 06:17:58.283356 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.022s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7346,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:58.284044 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87): free 8767140 bytes of WAL
I20260812 06:17:58.284268 19415 log_reader.cc:385] T f2dafcd29fb44ac991ee153ade3d0e87: removed 1 log segments from log reader
I20260812 06:17:58.284327 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000028 (ops 133-137)
I20260812 06:17:58.286247 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:58.286608 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:58.299229 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:58.299746 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:58.568017 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.268s	user 0.181s	sys 0.072s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37041193,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":265,"lbm_read_time_us":17928,"lbm_reads_lt_1ms":874,"lbm_write_time_us":47210,"lbm_writes_lt_1ms":843,"mutex_wait_us":37,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":27776,"thread_start_us":84,"threads_started":1,"update_count":4000}
I20260812 06:17:58.568806 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=18.063937
I20260812 06:17:58.636354 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.067s	user 0.028s	sys 0.028s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26356,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:58.636921 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:58.651113 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.014s	user 0.009s	sys 0.004s 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:17:58.651778 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:58.855352 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.203s	user 0.133s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1292,"lbm_read_time_us":13476,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36307,"lbm_writes_lt_1ms":643,"mutex_wait_us":575,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":3000}
I20260812 06:17:58.856104 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=15.087375
I20260812 06:17:58.908636 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.052s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":22839,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:58.909409 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:58.926466 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5675,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:58.927031 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:59.092800 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.166s	user 0.097s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733713,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":857,"lbm_read_time_us":9521,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28595,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:17:59.093524 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=14.095187
I20260812 06:17:59.139125 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.045s	user 0.018s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20330,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.139808 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:59.290607 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.151s	user 0.105s	sys 0.041s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1325,"lbm_read_time_us":9429,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24554,"lbm_writes_lt_1ms":443,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:59.291317 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=11.118625
I20260812 06:17:59.331962 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17317,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:59.332808 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:59.346935 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5084,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.347496 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:59.485105 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.137s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":531,"lbm_read_time_us":8239,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26503,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28928,"update_count":2000}
I20260812 06:17:59.486172 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=10.126437
I20260812 06:17:59.519349 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14254,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.520037 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:59.537919 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.538550 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:59.676644 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.138s	user 0.110s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":7809,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25335,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:17:59.677453 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=11.118625
I20260812 06:17:59.710299 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.033s	user 0.016s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13903,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:59.711113 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:59.727615 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.016s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5693,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.728106 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:59.772944 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushMRSOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.045s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":336,"dirs.run_wall_time_us":2079,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2119,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:59.773715 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=3.181125
I20260812 06:17:59.787632 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4406,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:59.788232 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87): free 120553636 bytes of WAL
I20260812 06:17:59.788614 19415 log_reader.cc:385] T f2dafcd29fb44ac991ee153ade3d0e87: removed 12 log segments from log reader
I20260812 06:17:59.788681 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000029 (ops 138-142)
I20260812 06:17:59.788722 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000030 (ops 143-147)
I20260812 06:17:59.788758 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000031 (ops 148-152)
I20260812 06:17:59.788785 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000032 (ops 153-157)
I20260812 06:17:59.788810 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000033 (ops 158-162)
I20260812 06:17:59.788837 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000034 (ops 163-167)
I20260812 06:17:59.788866 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000035 (ops 168-172)
I20260812 06:17:59.788888 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000036 (ops 173-176)
I20260812 06:17:59.788913 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000037 (ops 177-181)
I20260812 06:17:59.788939 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000038 (ops 182-186)
I20260812 06:17:59.788969 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000039 (ops 187-190)
I20260812 06:17:59.788991 19415 log.cc:1079] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/f2dafcd29fb44ac991ee153ade3d0e87/wal-000000040 (ops 191-195)
I20260812 06:17:59.822381 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: LogGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.034s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:17:59.822880 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87): 462 bytes on disk
I20260812 06:17:59.823530 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: UndoDeltaBlockGCOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:59.824205 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:59.846254 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.022s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4997,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.846763 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=2.188937
I20260812 06:17:59.858526 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: FlushDeltaMemStoresOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4614,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.858970 19490 maintenance_manager.cc:419] P 689f77e56a1945668b6cc606360ed586: Scheduling MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87): perf score=1.000000
I20260812 06:17:59.938941 19299 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.025s	user 1.853s	sys 0.139s
I20260812 06:18:00.047396 19299 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.108s	user 0.003s	sys 0.000s
I20260812 06:18:00.048066 19299 tablet_server.cc:179] TabletServer@127.18.216.193:0 shutting down...
I20260812 06:18:00.057371 19415 maintenance_manager.cc:643] P 689f77e56a1945668b6cc606360ed586: MajorDeltaCompactionOp(f2dafcd29fb44ac991ee153ade3d0e87) complete. Timing: real 0.198s	user 0.153s	sys 0.044s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938885,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":472,"lbm_read_time_us":15243,"lbm_reads_lt_1ms":771,"lbm_write_time_us":39623,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:18:00.058619 19299 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:00.059135 19299 tablet_replica.cc:333] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586: stopping tablet replica
I20260812 06:18:00.059427 19299 raft_consensus.cc:2243] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:00.059751 19299 raft_consensus.cc:2272] T f2dafcd29fb44ac991ee153ade3d0e87 P 689f77e56a1945668b6cc606360ed586 [term 1 FOLLOWER]: Raft consensus is shut down!
W20260812 06:18:00.074144 19366 debug-util.cc:398] Leaking SignalData structure 0x562960fec720 after lost signal to thread 19521
I20260812 06:18:00.082028 19299 tablet_server.cc:196] TabletServer@127.18.216.193:0 shutdown complete.
I20260812 06:18:00.119165 19299 master.cc:562] Master@127.18.216.254:35809 shutting down...
I20260812 06:18:00.125548 19299 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:00.125795 19299 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:00.125895 19299 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3734dadf6cbf4265bef44b0e81b5cfb2: stopping tablet replica
I20260812 06:18:00.417644 19299 master.cc:584] Master@127.18.216.254:35809 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5877 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:00.510454 19299 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.216.254:45027
I20260812 06:18:00.510918 19299 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:00.513624 19526 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:00.513674 19299 server_base.cc:1061] running on GCE node
W20260812 06:18:00.513664 19529 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:00.513643 19525 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:00.514096 19299 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:00.514153 19299 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:00.514186 19299 hybrid_clock.cc:648] HybridClock initialized: now 1786515480514185 us; error 0 us; skew 500 ppm
I20260812 06:18:00.515214 19299 webserver.cc:533] Webserver started at http://127.18.216.254:41157/ using document root <none> and password file <none>
I20260812 06:18:00.515355 19299 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:00.515399 19299 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:00.515462 19299 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:00.515821 19299 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/master-0-root/instance:
uuid: "799c6651e0914870a10d0302a7a2ede2"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-tm1g"
I20260812 06:18:00.517329 19299 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:00.518422 19534 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:00.518687 19299 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:00.518755 19299 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/master-0-root
uuid: "799c6651e0914870a10d0302a7a2ede2"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-tm1g"
I20260812 06:18:00.518859 19299 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-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:00.551101 19299 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:00.551595 19299 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:00.556236 19299 rpc_server.cc:307] RPC server started. Bound to: 127.18.216.254:45027
I20260812 06:18:00.558784 19596 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:00.559902 19595 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.216.254:45027 every 8 connection(s)
I20260812 06:18:00.576997 19596 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2: Bootstrap starting.
I20260812 06:18:00.578533 19596 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:00.580049 19596 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2: No bootstrap required, opened a new log
I20260812 06:18:00.580523 19596 raft_consensus.cc:359] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "799c6651e0914870a10d0302a7a2ede2" member_type: VOTER }
I20260812 06:18:00.580622 19596 raft_consensus.cc:385] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:00.580646 19596 raft_consensus.cc:740] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 799c6651e0914870a10d0302a7a2ede2, State: Initialized, Role: FOLLOWER
I20260812 06:18:00.580876 19596 consensus_queue.cc:260] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [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: "799c6651e0914870a10d0302a7a2ede2" member_type: VOTER }
I20260812 06:18:00.580973 19596 raft_consensus.cc:399] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:00.581034 19596 raft_consensus.cc:493] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:00.581100 19596 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:00.581835 19596 raft_consensus.cc:515] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "799c6651e0914870a10d0302a7a2ede2" member_type: VOTER }
I20260812 06:18:00.581957 19596 leader_election.cc:304] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [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: 799c6651e0914870a10d0302a7a2ede2; no voters: 
I20260812 06:18:00.582158 19596 leader_election.cc:290] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:00.582360 19599 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:00.582635 19599 raft_consensus.cc:697] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 1 LEADER]: Becoming Leader. State: Replica: 799c6651e0914870a10d0302a7a2ede2, State: Running, Role: LEADER
I20260812 06:18:00.582682 19596 sys_catalog.cc:565] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:00.582830 19599 consensus_queue.cc:237] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [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: "799c6651e0914870a10d0302a7a2ede2" member_type: VOTER }
I20260812 06:18:00.583292 19603 sys_catalog.cc:455] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 799c6651e0914870a10d0302a7a2ede2. Latest consensus state: current_term: 1 leader_uuid: "799c6651e0914870a10d0302a7a2ede2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "799c6651e0914870a10d0302a7a2ede2" member_type: VOTER } }
I20260812 06:18:00.583276 19602 sys_catalog.cc:455] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "799c6651e0914870a10d0302a7a2ede2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "799c6651e0914870a10d0302a7a2ede2" member_type: VOTER } }
I20260812 06:18:00.583395 19603 sys_catalog.cc:458] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:00.583405 19602 sys_catalog.cc:458] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:00.583701 19607 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:00.584484 19607 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:00.584746 19299 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:00.586828 19607 catalog_manager.cc:1383] Generated new cluster ID: 45de902ab83d4d7cb98302fc36f0c9db
I20260812 06:18:00.586917 19607 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:00.598078 19607 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:00.598773 19607 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:00.604835 19607 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2: Generated new TSK 0
I20260812 06:18:00.605067 19607 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:00.617435 19299 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:00.620085 19622 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:00.620217 19625 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:00.620132 19623 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:00.620429 19299 server_base.cc:1061] running on GCE node
I20260812 06:18:00.620635 19299 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:00.620682 19299 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:00.620699 19299 hybrid_clock.cc:648] HybridClock initialized: now 1786515480620699 us; error 0 us; skew 500 ppm
I20260812 06:18:00.626845 19299 webserver.cc:533] Webserver started at http://127.18.216.193:35095/ using document root <none> and password file <none>
I20260812 06:18:00.627034 19299 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:00.627076 19299 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:00.627142 19299 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:00.627555 19299 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/instance:
uuid: "c46923b1efc44a0f8695d2a9c185d618"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-tm1g"
I20260812 06:18:00.629236 19299 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:00.630404 19630 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:00.630769 19299 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:00.630882 19299 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root
uuid: "c46923b1efc44a0f8695d2a9c185d618"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-tm1g"
I20260812 06:18:00.630980 19299 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-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:00.642427 19299 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:00.642954 19299 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:00.643589 19299 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:00.644169 19299 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:00.644239 19299 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.644301 19299 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:00.644363 19299 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.649551 19299 rpc_server.cc:307] RPC server started. Bound to: 127.18.216.193:40451
I20260812 06:18:00.649643 19697 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.216.193:40451 every 8 connection(s)
I20260812 06:18:00.660636 19699 heartbeater.cc:344] Connected to a master server at 127.18.216.254:45027
I20260812 06:18:00.660815 19699 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:00.661154 19699 heartbeater.cc:507] Master 127.18.216.254:45027 requested a full tablet report, sending...
I20260812 06:18:00.662006 19555 ts_manager.cc:194] Registered new tserver with Master: c46923b1efc44a0f8695d2a9c185d618 (127.18.216.193:40451)
I20260812 06:18:00.662755 19299 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01267213s
I20260812 06:18:00.662887 19555 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49446
I20260812 06:18:00.671222 19555 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49452:
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:00.680495 19658 tablet_service.cc:1511] Processing CreateTablet for tablet 2b050445ca2047d6b8395b89c21e019c (DEFAULT_TABLE table=heavy-update-compaction-test [id=ce4e2dafa2c842309577ce8acda7d729]), partition=
I20260812 06:18:00.680814 19658 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2b050445ca2047d6b8395b89c21e019c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:00.683353 19715 tablet_bootstrap.cc:492] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Bootstrap starting.
I20260812 06:18:00.684417 19715 tablet_bootstrap.cc:654] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:00.685855 19715 tablet_bootstrap.cc:492] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: No bootstrap required, opened a new log
I20260812 06:18:00.685994 19715 ts_tablet_manager.cc:1403] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:00.686648 19715 raft_consensus.cc:359] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c46923b1efc44a0f8695d2a9c185d618" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 40451 } }
I20260812 06:18:00.686789 19715 raft_consensus.cc:385] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:00.686843 19715 raft_consensus.cc:740] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c46923b1efc44a0f8695d2a9c185d618, State: Initialized, Role: FOLLOWER
I20260812 06:18:00.687000 19715 consensus_queue.cc:260] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [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: "c46923b1efc44a0f8695d2a9c185d618" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 40451 } }
I20260812 06:18:00.687120 19715 raft_consensus.cc:399] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:00.687173 19715 raft_consensus.cc:493] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:00.687234 19715 raft_consensus.cc:3060] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:00.688099 19715 raft_consensus.cc:515] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c46923b1efc44a0f8695d2a9c185d618" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 40451 } }
I20260812 06:18:00.688274 19715 leader_election.cc:304] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [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: c46923b1efc44a0f8695d2a9c185d618; no voters: 
I20260812 06:18:00.688539 19715 leader_election.cc:290] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:00.688714 19717 raft_consensus.cc:2804] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:00.688941 19717 raft_consensus.cc:697] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 1 LEADER]: Becoming Leader. State: Replica: c46923b1efc44a0f8695d2a9c185d618, State: Running, Role: LEADER
I20260812 06:18:00.688979 19715 ts_tablet_manager.cc:1434] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:00.688992 19699 heartbeater.cc:499] Master 127.18.216.254:45027 was elected leader, sending a full tablet report...
I20260812 06:18:00.689123 19717 consensus_queue.cc:237] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [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: "c46923b1efc44a0f8695d2a9c185d618" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 40451 } }
I20260812 06:18:00.690578 19555 catalog_manager.cc:5719] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 reported cstate change: term changed from 0 to 1, leader changed from <none> to c46923b1efc44a0f8695d2a9c185d618 (127.18.216.193). New cstate: current_term: 1 leader_uuid: "c46923b1efc44a0f8695d2a9c185d618" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c46923b1efc44a0f8695d2a9c185d618" member_type: VOTER last_known_addr { host: "127.18.216.193" port: 40451 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:00.752358 19299 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.017s	sys 0.008s
I20260812 06:18:00.900727 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushMRSOp(2b050445ca2047d6b8395b89c21e019c): perf score=15.086190
I20260812 06:18:01.044750 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushMRSOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.144s	user 0.119s	sys 0.020s Metrics: {"bytes_written":11897251,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1400,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36135,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:18:01.045424 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling LogGCOp(2b050445ca2047d6b8395b89c21e019c): free 20743880 bytes of WAL
I20260812 06:18:01.045661 19635 log_reader.cc:385] T 2b050445ca2047d6b8395b89c21e019c: removed 2 log segments from log reader
I20260812 06:18:01.045706 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000001 (ops 1-6)
I20260812 06:18:01.045735 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000002 (ops 7-11)
I20260812 06:18:01.050007 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: LogGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:01.050485 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:01.067747 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.017s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.068356 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c): 12719217 bytes on disk
I20260812 06:18:01.068810 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c) 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:01.069272 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:01.207370 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.138s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262038,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":511,"lbm_read_time_us":10712,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25534,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":314,"threads_started":5,"update_count":1950}
I20260812 06:18:01.207939 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:01.245110 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.037s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13856,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.245679 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:01.261036 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.261775 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:01.397190 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.135s	user 0.107s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":10527,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25070,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:18:01.397765 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:01.443768 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.046s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15224,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.444342 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:01.455551 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.456023 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:01.618916 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.163s	user 0.115s	sys 0.048s 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":186,"lbm_read_time_us":11192,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26585,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:01.619573 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:01.666834 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.047s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14827,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.667366 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:01.678732 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.679477 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:01.820247 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.141s	user 0.104s	sys 0.036s 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":152,"lbm_read_time_us":10583,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27037,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:01.821059 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:01.866834 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.046s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16973,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.867301 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:01.878340 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.879112 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:02.016153 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.137s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":954,"lbm_read_time_us":10424,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25901,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:18:02.016937 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:02.072202 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.055s	user 0.028s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18897,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.072767 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:02.085193 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.085721 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:02.241469 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.156s	user 0.107s	sys 0.048s 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":414,"lbm_read_time_us":12461,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23972,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:18:02.242354 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:02.291693 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.049s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18922,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.292312 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:02.309031 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.309686 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:02.441874 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.132s	user 0.116s	sys 0.016s 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":334,"lbm_read_time_us":10797,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23745,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:18:02.442613 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:02.489145 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.046s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16798,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.489701 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:02.503688 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.504390 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushMRSOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:02.537688 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushMRSOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":340,"dirs.run_wall_time_us":1766,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2006,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:02.538475 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling LogGCOp(2b050445ca2047d6b8395b89c21e019c): free 121006437 bytes of WAL
I20260812 06:18:02.538753 19635 log_reader.cc:385] T 2b050445ca2047d6b8395b89c21e019c: removed 12 log segments from log reader
I20260812 06:18:02.538816 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000003 (ops 12-16)
I20260812 06:18:02.538857 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000004 (ops 17-21)
I20260812 06:18:02.538888 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000005 (ops 22-26)
I20260812 06:18:02.538914 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000006 (ops 27-31)
I20260812 06:18:02.538942 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000007 (ops 32-36)
I20260812 06:18:02.538968 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000008 (ops 37-41)
I20260812 06:18:02.539000 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000009 (ops 42-46)
I20260812 06:18:02.539026 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000010 (ops 47-51)
I20260812 06:18:02.539060 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000011 (ops 52-56)
I20260812 06:18:02.539099 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000012 (ops 57-60)
I20260812 06:18:02.539129 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000013 (ops 61-65)
I20260812 06:18:02.539157 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000014 (ops 66-70)
I20260812 06:18:02.569299 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: LogGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:02.569749 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c): 482 bytes on disk
I20260812 06:18:02.570241 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.570819 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=3.181125
I20260812 06:18:02.590265 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7603,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:02.590816 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:02.600755 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3598,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.601266 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:02.771759 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.170s	user 0.138s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":606,"lbm_read_time_us":12882,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33542,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:18:02.772433 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=14.095187
I20260812 06:18:02.830269 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.058s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22918,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.830909 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:02.842075 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4414,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.842710 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:03.003908 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.161s	user 0.123s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":12368,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33240,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":115,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:18:03.004698 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=11.118625
I20260812 06:18:03.038566 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.034s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14685,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:03.039194 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:03.052176 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4792,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:03.052845 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:03.184122 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.131s	user 0.096s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":8836,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25417,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:18:03.184893 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=11.118625
I20260812 06:18:03.240072 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.055s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17467,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:03.240514 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:03.251649 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.252126 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:03.261935 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.010s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3765,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:03.262482 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:03.435253 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.173s	user 0.124s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":257,"lbm_read_time_us":12267,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29698,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2500}
I20260812 06:18:03.435985 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=14.095187
I20260812 06:18:03.495920 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.060s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20774,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.496557 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:03.507328 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.507810 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:03.687716 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.180s	user 0.109s	sys 0.070s 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":347,"lbm_read_time_us":14833,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30628,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2500}
I20260812 06:18:03.690783 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:03.728925 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.038s	user 0.009s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16883,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.729516 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:03.743017 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4703,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.743600 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:03.914726 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.171s	user 0.118s	sys 0.052s 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":673,"lbm_read_time_us":11914,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27207,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2000}
I20260812 06:18:03.915478 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=10.126437
I20260812 06:18:03.955602 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.040s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18412,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.956212 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:03.974644 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.018s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.975238 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushMRSOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:04.033391 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushMRSOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.058s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1610,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1775,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:04.034055 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling LogGCOp(2b050445ca2047d6b8395b89c21e019c): free 124257193 bytes of WAL
I20260812 06:18:04.034293 19635 log_reader.cc:385] T 2b050445ca2047d6b8395b89c21e019c: removed 12 log segments from log reader
I20260812 06:18:04.034401 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000015 (ops 71-75)
I20260812 06:18:04.034433 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000016 (ops 76-80)
I20260812 06:18:04.034485 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000017 (ops 81-85)
I20260812 06:18:04.034538 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000018 (ops 86-90)
I20260812 06:18:04.034571 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000019 (ops 91-95)
I20260812 06:18:04.034607 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000020 (ops 96-100)
I20260812 06:18:04.034648 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000021 (ops 101-104)
I20260812 06:18:04.034687 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000022 (ops 105-109)
I20260812 06:18:04.034726 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000023 (ops 110-114)
I20260812 06:18:04.034765 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000024 (ops 115-119)
I20260812 06:18:04.034803 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000025 (ops 120-124)
I20260812 06:18:04.034842 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000026 (ops 125-129)
I20260812 06:18:04.065426 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: LogGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:04.065976 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c): 472 bytes on disk
I20260812 06:18:04.066682 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.067245 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=7.149875
I20260812 06:18:04.103529 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11275,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:04.104118 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling LogGCOp(2b050445ca2047d6b8395b89c21e019c): free 12018006 bytes of WAL
I20260812 06:18:04.104350 19635 log_reader.cc:385] T 2b050445ca2047d6b8395b89c21e019c: removed 1 log segments from log reader
I20260812 06:18:04.104395 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000027 (ops 130-134)
I20260812 06:18:04.107106 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: LogGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:04.107503 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:04.123356 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5128,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.123832 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:04.359077 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.235s	user 0.163s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2291,"lbm_read_time_us":15841,"lbm_reads_lt_1ms":770,"lbm_write_time_us":39100,"lbm_writes_lt_1ms":743,"mutex_wait_us":2085,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:18:04.360121 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=15.087375
I20260812 06:18:04.422210 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.062s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":23924,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:04.422808 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:04.439958 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.440446 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:04.450348 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3735,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.450899 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:04.671331 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.220s	user 0.145s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":252,"lbm_read_time_us":15123,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37461,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":45312,"update_count":3000}
I20260812 06:18:04.672096 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=14.095187
I20260812 06:18:04.741560 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.069s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27412,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.742134 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:04.754812 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4546,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.755384 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:04.930356 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.175s	user 0.127s	sys 0.043s 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":332,"lbm_read_time_us":12900,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28822,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":67328,"update_count":2500}
I20260812 06:18:04.930922 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=14.095187
I20260812 06:18:04.987687 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.057s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20800,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.988247 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:04.999248 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4368,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.999867 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:05.182480 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.182s	user 0.107s	sys 0.067s 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":737,"lbm_read_time_us":11499,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32935,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:05.183324 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=14.095187
I20260812 06:18:05.242259 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.059s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21734,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.242908 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:05.253841 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.254441 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:05.438817 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.184s	user 0.111s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":499,"lbm_read_time_us":13575,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29809,"lbm_writes_lt_1ms":543,"mutex_wait_us":263,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:18:05.439641 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=11.118625
I20260812 06:18:05.485678 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.046s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16495,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:05.486366 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:05.509599 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.023s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4143686,"delete_count":0,"lbm_write_time_us":4371,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:18:05.510268 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:05.525000 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":5331,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:18:05.525699 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushMRSOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:05.571987 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushMRSOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.046s	user 0.024s	sys 0.008s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1457,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1673,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:05.572675 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling LogGCOp(2b050445ca2047d6b8395b89c21e019c): free 112692556 bytes of WAL
I20260812 06:18:05.572919 19635 log_reader.cc:385] T 2b050445ca2047d6b8395b89c21e019c: removed 11 log segments from log reader
I20260812 06:18:05.572966 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000028 (ops 135-139)
I20260812 06:18:05.572996 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000029 (ops 140-144)
I20260812 06:18:05.573060 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000030 (ops 145-149)
I20260812 06:18:05.573119 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000031 (ops 150-154)
I20260812 06:18:05.573160 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000032 (ops 155-159)
I20260812 06:18:05.573199 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000033 (ops 160-164)
I20260812 06:18:05.573241 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000034 (ops 165-169)
I20260812 06:18:05.573280 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000035 (ops 170-174)
I20260812 06:18:05.573319 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000036 (ops 175-179)
I20260812 06:18:05.573357 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000037 (ops 180-184)
I20260812 06:18:05.573405 19635 log.cc:1079] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: Deleting log segment in path: /tmp/dist-test-task3sdz1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515474622407-19299-0/minicluster-data/ts-0-root/wals/2b050445ca2047d6b8395b89c21e019c/wal-000000038 (ops 185-189)
I20260812 06:18:05.598963 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: LogGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:05.599403 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=3.181125
I20260812 06:18:05.619611 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.020s	user 0.003s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5038,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:05.620074 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:05.629909 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3843,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.630435 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:05.863250 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.233s	user 0.160s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":54,"lbm_read_time_us":15922,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39416,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17024,"thread_start_us":105,"threads_started":1,"update_count":3500}
I20260812 06:18:05.865389 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=14.095187
I20260812 06:18:05.887984 19299 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.136s	user 1.847s	sys 0.210s
I20260812 06:18:05.903769 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.038s	user 0.030s	sys 0.007s Metrics: {"bytes_written":16615024,"delete_count":0,"lbm_write_time_us":18246,"lbm_writes_lt_1ms":408,"reinsert_count":0,"update_count":2025}
I20260812 06:18:05.904340 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c): perf score=2.188937
I20260812 06:18:05.916456 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: FlushDeltaMemStoresOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3897533,"delete_count":0,"lbm_write_time_us":3957,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:05.917006 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c): 448 bytes on disk
I20260812 06:18:05.917444 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: UndoDeltaBlockGCOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.917944 19701 maintenance_manager.cc:419] P c46923b1efc44a0f8695d2a9c185d618: Scheduling MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c): perf score=1.000000
I20260812 06:18:05.935979 19299 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.047s	user 0.001s	sys 0.000s
I20260812 06:18:05.936563 19299 tablet_server.cc:179] TabletServer@127.18.216.193:0 shutting down...
I20260812 06:18:06.058931 19635 maintenance_manager.cc:643] P c46923b1efc44a0f8695d2a9c185d618: MajorDeltaCompactionOp(2b050445ca2047d6b8395b89c21e019c) complete. Timing: real 0.141s	user 0.093s	sys 0.047s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512295,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1648,"lbm_read_time_us":8484,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24014,"lbm_writes_lt_1ms":543,"mutex_wait_us":453,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:06.059676 19299 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:06.059943 19299 tablet_replica.cc:333] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618: stopping tablet replica
I20260812 06:18:06.060127 19299 raft_consensus.cc:2243] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:06.060315 19299 raft_consensus.cc:2272] T 2b050445ca2047d6b8395b89c21e019c P c46923b1efc44a0f8695d2a9c185d618 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:06.065568 19299 tablet_server.cc:196] TabletServer@127.18.216.193:0 shutdown complete.
I20260812 06:18:06.105396 19299 master.cc:562] Master@127.18.216.254:45027 shutting down...
I20260812 06:18:06.109860 19299 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:06.110080 19299 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:06.110164 19299 tablet_replica.cc:333] T 00000000000000000000000000000000 P 799c6651e0914870a10d0302a7a2ede2: stopping tablet replica
I20260812 06:18:06.122798 19299 master.cc:584] Master@127.18.216.254:45027 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5705 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11583 ms total)

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