[==========] 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:16:36.920835  3832 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.190.62:34167
I20260812 06:16:36.921772  3832 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:16:36.922302  3832 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:36.928138  3832 server_base.cc:1061] running on GCE node
W20260812 06:16:36.928148  3840 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:16:36.928272  3844 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:16:36.928094  3842 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:16:36.928776  3832 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:36.928864  3832 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:16:36.928915  3832 hybrid_clock.cc:648] HybridClock initialized: now 1786515396928912 us; error 0 us; skew 500 ppm
I20260812 06:16:36.930508  3832 webserver.cc:533] Webserver started at http://127.3.190.62:38363/ using document root <none> and password file <none>
I20260812 06:16:36.930992  3832 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:36.931053  3832 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:36.931258  3832 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:36.932739  3832 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/master-0-root/instance:
uuid: "5707abba39294c759632a619319e7a8c"
format_stamp: "Formatted at 2026-08-12 06:16:36 on dist-test-slave-gjw7"
I20260812 06:16:36.935847  3832 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.002s
I20260812 06:16:36.937733  3853 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:16:36.938588  3832 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:36.938684  3832 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/master-0-root
uuid: "5707abba39294c759632a619319e7a8c"
format_stamp: "Formatted at 2026-08-12 06:16:36 on dist-test-slave-gjw7"
I20260812 06:16:36.938762  3832 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-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:16:36.957055  3832 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:36.957657  3832 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:16:36.957805  3832 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:36.964529  3832 rpc_server.cc:307] RPC server started. Bound to: 127.3.190.62:34167
I20260812 06:16:36.964562  3974 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.190.62:34167 every 8 connection(s)
I20260812 06:16:36.966590  3976 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:16:36.971792  3976 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c: Bootstrap starting.
I20260812 06:16:36.974066  3976 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:36.974924  3976 log.cc:826] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:36.976502  3976 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c: No bootstrap required, opened a new log
I20260812 06:16:36.979197  3976 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5707abba39294c759632a619319e7a8c" member_type: VOTER }
I20260812 06:16:36.979357  3976 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:36.979435  3976 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5707abba39294c759632a619319e7a8c, State: Initialized, Role: FOLLOWER
I20260812 06:16:36.979988  3976 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [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: "5707abba39294c759632a619319e7a8c" member_type: VOTER }
I20260812 06:16:36.980132  3976 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:36.980207  3976 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:36.980324  3976 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:36.981047  3976 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5707abba39294c759632a619319e7a8c" member_type: VOTER }
I20260812 06:16:36.981487  3976 leader_election.cc:304] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [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: 5707abba39294c759632a619319e7a8c; no voters: 
I20260812 06:16:36.981791  3976 leader_election.cc:290] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:36.981895  3984 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:36.982088  3984 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 1 LEADER]: Becoming Leader. State: Replica: 5707abba39294c759632a619319e7a8c, State: Running, Role: LEADER
I20260812 06:16:36.982497  3984 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [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: "5707abba39294c759632a619319e7a8c" member_type: VOTER }
I20260812 06:16:36.982697  3976 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:36.984112  3987 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5707abba39294c759632a619319e7a8c. Latest consensus state: current_term: 1 leader_uuid: "5707abba39294c759632a619319e7a8c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5707abba39294c759632a619319e7a8c" member_type: VOTER } }
I20260812 06:16:36.984150  3986 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5707abba39294c759632a619319e7a8c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5707abba39294c759632a619319e7a8c" member_type: VOTER } }
I20260812 06:16:36.984211  3987 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:36.984237  3986 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:36.984565  3998 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:36.986828  3998 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:36.987140  3832 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:36.991425  3998 catalog_manager.cc:1383] Generated new cluster ID: 4fd50ab218084a3db59df909892fcb98
I20260812 06:16:36.991487  3998 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:37.005832  3998 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:37.006899  3998 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:37.013207  3998 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c: Generated new TSK 0
I20260812 06:16:37.013769  3998 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:37.019443  3832 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:37.021793  4010 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:16:37.021906  4022 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:16:37.022064  3832 server_base.cc:1061] running on GCE node
W20260812 06:16:37.022104  4012 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:16:37.022287  3832 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:37.022329  3832 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:16:37.022343  3832 hybrid_clock.cc:648] HybridClock initialized: now 1786515397022343 us; error 0 us; skew 500 ppm
I20260812 06:16:37.023155  3832 webserver.cc:533] Webserver started at http://127.3.190.1:41347/ using document root <none> and password file <none>
I20260812 06:16:37.023295  3832 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:37.023342  3832 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:37.023427  3832 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:37.023767  3832 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/instance:
uuid: "a4fc66ea3eee4449938558ee1b4c2231"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-gjw7"
I20260812 06:16:37.025125  3832 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:37.026087  4039 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:16:37.026340  3832 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:37.026412  3832 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root
uuid: "a4fc66ea3eee4449938558ee1b4c2231"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-gjw7"
I20260812 06:16:37.026484  3832 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-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:16:37.045822  3832 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:37.046198  3832 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:37.046638  3832 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:37.047411  3832 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:37.047462  3832 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.047518  3832 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:37.047541  3832 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.053635  3832 rpc_server.cc:307] RPC server started. Bound to: 127.3.190.1:39531
I20260812 06:16:37.053670  4160 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.190.1:39531 every 8 connection(s)
I20260812 06:16:37.065982  4164 heartbeater.cc:344] Connected to a master server at 127.3.190.62:34167
I20260812 06:16:37.066196  4164 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:37.066637  4164 heartbeater.cc:507] Master 127.3.190.62:34167 requested a full tablet report, sending...
I20260812 06:16:37.068009  3901 ts_manager.cc:194] Registered new tserver with Master: a4fc66ea3eee4449938558ee1b4c2231 (127.3.190.1:39531)
I20260812 06:16:37.068571  3832 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014373893s
I20260812 06:16:37.069538  3901 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39004
I20260812 06:16:37.076851  3901 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39012:
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:16:37.089704  4096 tablet_service.cc:1511] Processing CreateTablet for tablet 522d1f8e3a69481395439b2e651d779e (DEFAULT_TABLE table=heavy-update-compaction-test [id=dc1f5ab9766941a58269458e8b3d2240]), partition=
I20260812 06:16:37.090111  4096 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 522d1f8e3a69481395439b2e651d779e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:37.092025  4201 tablet_bootstrap.cc:492] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Bootstrap starting.
I20260812 06:16:37.092931  4201 tablet_bootstrap.cc:654] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:37.093990  4201 tablet_bootstrap.cc:492] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: No bootstrap required, opened a new log
I20260812 06:16:37.094070  4201 ts_tablet_manager.cc:1403] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:16:37.094481  4201 raft_consensus.cc:359] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4fc66ea3eee4449938558ee1b4c2231" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 39531 } }
I20260812 06:16:37.094574  4201 raft_consensus.cc:385] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:37.094596  4201 raft_consensus.cc:740] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4fc66ea3eee4449938558ee1b4c2231, State: Initialized, Role: FOLLOWER
I20260812 06:16:37.094707  4201 consensus_queue.cc:260] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [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: "a4fc66ea3eee4449938558ee1b4c2231" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 39531 } }
I20260812 06:16:37.094782  4201 raft_consensus.cc:399] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:37.094818  4201 raft_consensus.cc:493] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:37.094875  4201 raft_consensus.cc:3060] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:37.095536  4201 raft_consensus.cc:515] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4fc66ea3eee4449938558ee1b4c2231" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 39531 } }
I20260812 06:16:37.095652  4201 leader_election.cc:304] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [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: a4fc66ea3eee4449938558ee1b4c2231; no voters: 
I20260812 06:16:37.095831  4201 leader_election.cc:290] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:37.095999  4212 raft_consensus.cc:2804] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:37.096176  4201 ts_tablet_manager.cc:1434] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:37.096397  4164 heartbeater.cc:499] Master 127.3.190.62:34167 was elected leader, sending a full tablet report...
I20260812 06:16:37.096262  4212 raft_consensus.cc:697] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 1 LEADER]: Becoming Leader. State: Replica: a4fc66ea3eee4449938558ee1b4c2231, State: Running, Role: LEADER
I20260812 06:16:37.096767  4212 consensus_queue.cc:237] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [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: "a4fc66ea3eee4449938558ee1b4c2231" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 39531 } }
I20260812 06:16:37.099246  3901 catalog_manager.cc:5719] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 reported cstate change: term changed from 0 to 1, leader changed from <none> to a4fc66ea3eee4449938558ee1b4c2231 (127.3.190.1). New cstate: current_term: 1 leader_uuid: "a4fc66ea3eee4449938558ee1b4c2231" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4fc66ea3eee4449938558ee1b4c2231" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 39531 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:37.159102  3832 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.013s	sys 0.011s
I20260812 06:16:37.304734  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushMRSOp(522d1f8e3a69481395439b2e651d779e): perf score=19.054940
I20260812 06:16:37.468700  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushMRSOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.164s	user 0.127s	sys 0.032s Metrics: {"bytes_written":12389530,"cfile_init":1,"compiler_manager_pool.queue_time_us":180,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":856,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40540,"lbm_writes_lt_1ms":769,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":273664,"thread_start_us":88,"threads_started":1,"update_count":1510}
I20260812 06:16:37.470052  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling LogGCOp(522d1f8e3a69481395439b2e651d779e): free 20743880 bytes of WAL
I20260812 06:16:37.470430  4044 log_reader.cc:385] T 522d1f8e3a69481395439b2e651d779e: removed 2 log segments from log reader
I20260812 06:16:37.470556  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000001 (ops 1-6)
I20260812 06:16:37.470672  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000002 (ops 7-11)
I20260812 06:16:37.475353  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: LogGCOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:37.475768  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e): 16821651 bytes on disk
I20260812 06:16:37.476428  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e) 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:16:37.476873  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:37.501541  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.025s	user 0.010s	sys 0.010s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":5637,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:16:37.501951  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:37.510684  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3209,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:37.511090  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:37.678910  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.168s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405539,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":322,"lbm_read_time_us":10365,"lbm_reads_lt_1ms":559,"lbm_write_time_us":27873,"lbm_writes_lt_1ms":533,"mutex_wait_us":25,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":281,"threads_started":5,"update_count":2450}
I20260812 06:16:37.679399  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:37.722100  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.043s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14571,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.722553  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:37.732292  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.732748  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:37.847949  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.115s	user 0.094s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":9611,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19914,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:37.848598  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:37.891934  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.043s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13072,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.892407  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:37.903570  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.904031  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:38.019874  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.116s	user 0.087s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":657,"lbm_read_time_us":6983,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21490,"lbm_writes_lt_1ms":443,"mutex_wait_us":252,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.021792  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:38.058708  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.037s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15903,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.059190  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:38.069823  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.070711  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:38.191043  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.120s	user 0.089s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1021,"lbm_read_time_us":7893,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23932,"lbm_writes_lt_1ms":443,"mutex_wait_us":304,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.191514  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:38.236009  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.044s	user 0.010s	sys 0.032s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15218,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.236545  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:38.251230  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.251694  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:38.394919  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.143s	user 0.113s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":732,"lbm_read_time_us":10343,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22400,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.395395  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:38.454922  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.059s	user 0.009s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":42686,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.455329  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:38.466095  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.466547  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:38.580145  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.113s	user 0.093s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":6978,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22454,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:16:38.580647  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:38.618111  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.037s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13171,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.618575  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:38.627990  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.628379  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushMRSOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:38.659042  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushMRSOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1302,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1964,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:38.659931  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling LogGCOp(522d1f8e3a69481395439b2e651d779e): free 115943173 bytes of WAL
I20260812 06:16:38.660188  4044 log_reader.cc:385] T 522d1f8e3a69481395439b2e651d779e: removed 11 log segments from log reader
I20260812 06:16:38.660239  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000003 (ops 12-16)
I20260812 06:16:38.660276  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000004 (ops 17-21)
I20260812 06:16:38.660308  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000005 (ops 22-26)
I20260812 06:16:38.660333  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000006 (ops 27-31)
I20260812 06:16:38.660363  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000007 (ops 32-36)
I20260812 06:16:38.660403  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000008 (ops 37-41)
I20260812 06:16:38.660432  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000009 (ops 42-46)
I20260812 06:16:38.660462  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000010 (ops 47-51)
I20260812 06:16:38.660491  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000011 (ops 52-56)
I20260812 06:16:38.660521  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000012 (ops 57-61)
I20260812 06:16:38.660550  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000013 (ops 62-66)
I20260812 06:16:38.680877  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: LogGCOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.021s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:16:38.681316  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e): 447 bytes on disk
I20260812 06:16:38.681748  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:38.682251  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=3.181125
I20260812 06:16:38.695384  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3988,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:38.695830  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:38.709035  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4914,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:38.709554  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:38.883404  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.174s	user 0.136s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2186,"lbm_read_time_us":11620,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35955,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:16:38.884028  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=14.095187
I20260812 06:16:38.933175  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.049s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20378,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.933617  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:38.949366  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.949918  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:39.098589  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.148s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":10250,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26236,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":76544,"update_count":2500}
I20260812 06:16:39.099064  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=14.095187
I20260812 06:16:39.140436  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17583,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.140988  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:39.276518  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.135s	user 0.099s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":309,"lbm_read_time_us":9774,"lbm_reads_lt_1ms":467,"lbm_write_time_us":20553,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":615424,"update_count":2000}
I20260812 06:16:39.277093  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=11.118625
I20260812 06:16:39.305254  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.028s	user 0.018s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11881,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.305727  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:39.319180  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.013s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3686,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.319674  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:39.435669  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.116s	user 0.075s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":893,"lbm_read_time_us":7908,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21064,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:16:39.436187  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:39.478284  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.042s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13207,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.478807  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:39.493724  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.494377  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:39.611505  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.117s	user 0.099s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":519,"lbm_read_time_us":8492,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21891,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":41728,"update_count":2000}
I20260812 06:16:39.611990  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:39.645637  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13691,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.646083  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:39.655639  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.656282  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:39.765569  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.109s	user 0.085s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":81,"lbm_read_time_us":7269,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20324,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":77696,"update_count":2000}
I20260812 06:16:39.766186  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:39.810880  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.044s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13689,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.811532  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:39.826753  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5712,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.827313  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:39.975343  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.148s	user 0.091s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":11788,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23846,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:39.975849  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:40.012534  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.036s	user 0.023s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12310,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.013033  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:40.023052  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.023653  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushMRSOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:40.055393  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushMRSOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1231,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1324,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:40.056188  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling LogGCOp(522d1f8e3a69481395439b2e651d779e): free 133477376 bytes of WAL
I20260812 06:16:40.056416  4044 log_reader.cc:385] T 522d1f8e3a69481395439b2e651d779e: removed 13 log segments from log reader
I20260812 06:16:40.056465  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000014 (ops 67-71)
I20260812 06:16:40.056504  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000015 (ops 72-76)
I20260812 06:16:40.056535  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000016 (ops 77-81)
I20260812 06:16:40.056561  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000017 (ops 82-86)
I20260812 06:16:40.056591  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000018 (ops 87-91)
I20260812 06:16:40.056622  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000019 (ops 92-96)
I20260812 06:16:40.056653  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000020 (ops 97-101)
I20260812 06:16:40.056684  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000021 (ops 102-106)
I20260812 06:16:40.056710  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000022 (ops 107-111)
I20260812 06:16:40.056748  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000023 (ops 112-116)
I20260812 06:16:40.056779  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000024 (ops 117-121)
I20260812 06:16:40.056808  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000025 (ops 122-126)
I20260812 06:16:40.056838  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000026 (ops 127-131)
I20260812 06:16:40.079614  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: LogGCOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:40.080174  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=3.181125
I20260812 06:16:40.102476  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.022s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4718029,"delete_count":0,"lbm_write_time_us":6757,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:16:40.102897  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:40.111969  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":3354,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:16:40.112361  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e): 482 bytes on disk
I20260812 06:16:40.112738  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e) 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:16:40.113193  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:40.308584  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.195s	user 0.135s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":526,"lbm_read_time_us":12725,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31412,"lbm_writes_lt_1ms":643,"mutex_wait_us":288,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:16:40.309070  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=14.095187
I20260812 06:16:40.364486  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.055s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19682,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.365100  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:40.375375  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3740,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.375888  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:40.542176  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.166s	user 0.132s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":868,"lbm_read_time_us":10988,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26271,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:16:40.542748  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=11.118625
I20260812 06:16:40.572039  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.029s	user 0.011s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11710,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:40.572583  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:40.585199  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.585768  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:40.712446  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.126s	user 0.106s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":8139,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23868,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:16:40.712939  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:40.752149  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.039s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15818,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.752702  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:40.764206  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.764709  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:40.885963  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.121s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":316,"lbm_read_time_us":8198,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23793,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:16:40.886598  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=10.126437
I20260812 06:16:40.924803  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.038s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15963,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.925401  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:40.938192  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4435,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.938668  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:41.073030  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.134s	user 0.102s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":8200,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24402,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:16:41.073590  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=14.095187
I20260812 06:16:41.121526  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.048s	user 0.033s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19384,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.122092  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:41.132033  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.132547  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:41.303381  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.171s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":655,"lbm_read_time_us":12523,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28357,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:41.303975  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=14.095187
I20260812 06:16:41.353425  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.049s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17711,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.354014  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:41.363850  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.364367  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushMRSOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:41.401885  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushMRSOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.037s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":164,"dirs.run_wall_time_us":1191,"drs_written":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1317,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":14720}
I20260812 06:16:41.402628  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling LogGCOp(522d1f8e3a69481395439b2e651d779e): free 120553644 bytes of WAL
I20260812 06:16:41.402877  4044 log_reader.cc:385] T 522d1f8e3a69481395439b2e651d779e: removed 12 log segments from log reader
I20260812 06:16:41.402927  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000027 (ops 132-136)
I20260812 06:16:41.402964  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000028 (ops 137-141)
I20260812 06:16:41.402997  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000029 (ops 142-146)
I20260812 06:16:41.403021  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000030 (ops 147-151)
I20260812 06:16:41.403053  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000031 (ops 152-156)
I20260812 06:16:41.403083  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000032 (ops 157-161)
I20260812 06:16:41.403115  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000033 (ops 162-166)
I20260812 06:16:41.403144  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000034 (ops 167-170)
I20260812 06:16:41.403173  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000035 (ops 171-175)
I20260812 06:16:41.403246  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000036 (ops 176-180)
I20260812 06:16:41.403275  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000037 (ops 181-184)
I20260812 06:16:41.403304  4044 log.cc:1079] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/522d1f8e3a69481395439b2e651d779e/wal-000000038 (ops 185-189)
I20260812 06:16:41.423875  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: LogGCOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:16:41.424300  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e): 463 bytes on disk
I20260812 06:16:41.424750  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: UndoDeltaBlockGCOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.425417  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=3.181125
I20260812 06:16:41.442668  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.017s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:41.443111  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:41.455964  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4652,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.456487  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e): perf score=1.000000
I20260812 06:16:41.663851  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: MajorDeltaCompactionOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.207s	user 0.152s	sys 0.047s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1551,"lbm_read_time_us":14491,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35999,"lbm_writes_lt_1ms":743,"mutex_wait_us":251,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10240,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:16:41.664539  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=15.087375
I20260812 06:16:41.682871  3832 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.524s	user 1.646s	sys 0.133s
I20260812 06:16:41.725435  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.061s	user 0.034s	sys 0.027s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":26654,"lbm_writes_lt_1ms":413,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2050}
I20260812 06:16:41.726085  4166 maintenance_manager.cc:419] P a4fc66ea3eee4449938558ee1b4c2231: Scheduling FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e): perf score=2.188937
I20260812 06:16:41.731050  3832 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.048s	user 0.002s	sys 0.000s
I20260812 06:16:41.731608  3832 tablet_server.cc:179] TabletServer@127.3.190.1:0 shutting down...
I20260812 06:16:41.739521  4044 maintenance_manager.cc:643] P a4fc66ea3eee4449938558ee1b4c2231: FlushDeltaMemStoresOp(522d1f8e3a69481395439b2e651d779e) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5191,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.739995  3832 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:41.740340  3832 tablet_replica.cc:333] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231: stopping tablet replica
I20260812 06:16:41.740540  3832 raft_consensus.cc:2243] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:41.740760  3832 raft_consensus.cc:2272] T 522d1f8e3a69481395439b2e651d779e P a4fc66ea3eee4449938558ee1b4c2231 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:41.755403  3832 tablet_server.cc:196] TabletServer@127.3.190.1:0 shutdown complete.
I20260812 06:16:41.760428  3832 master.cc:562] Master@127.3.190.62:34167 shutting down...
I20260812 06:16:41.764051  3832 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:41.764218  3832 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:41.764288  3832 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5707abba39294c759632a619319e7a8c: stopping tablet replica
I20260812 06:16:41.776443  3832 master.cc:584] Master@127.3.190.62:34167 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4932 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:41.852432  3832 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.190.62:44607
I20260812 06:16:41.852814  3832 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:41.854734  4238 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:16:41.854804  4242 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:16:41.854909  4245 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:16:41.854969  3832 server_base.cc:1061] running on GCE node
I20260812 06:16:41.855139  3832 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:41.855175  3832 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:16:41.855194  3832 hybrid_clock.cc:648] HybridClock initialized: now 1786515401855194 us; error 0 us; skew 500 ppm
I20260812 06:16:41.856029  3832 webserver.cc:533] Webserver started at http://127.3.190.62:39813/ using document root <none> and password file <none>
I20260812 06:16:41.856179  3832 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:41.856223  3832 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:41.856289  3832 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:41.856642  3832 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/master-0-root/instance:
uuid: "f613035d10864f9d875b502994a94a7d"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-gjw7"
I20260812 06:16:41.858122  3832 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:41.858932  4258 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:16:41.859129  3832 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:41.859200  3832 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/master-0-root
uuid: "f613035d10864f9d875b502994a94a7d"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-gjw7"
I20260812 06:16:41.859266  3832 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-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:16:41.869081  3832 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:41.869433  3832 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:41.873271  3832 rpc_server.cc:307] RPC server started. Bound to: 127.3.190.62:44607
I20260812 06:16:41.887357  4356 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:16:41.887377  4355 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.190.62:44607 every 8 connection(s)
I20260812 06:16:41.889248  4356 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d: Bootstrap starting.
I20260812 06:16:41.890059  4356 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:41.891042  4356 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d: No bootstrap required, opened a new log
I20260812 06:16:41.891451  4356 raft_consensus.cc:359] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f613035d10864f9d875b502994a94a7d" member_type: VOTER }
I20260812 06:16:41.891536  4356 raft_consensus.cc:385] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:41.891566  4356 raft_consensus.cc:740] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f613035d10864f9d875b502994a94a7d, State: Initialized, Role: FOLLOWER
I20260812 06:16:41.891696  4356 consensus_queue.cc:260] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [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: "f613035d10864f9d875b502994a94a7d" member_type: VOTER }
I20260812 06:16:41.891767  4356 raft_consensus.cc:399] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:41.891804  4356 raft_consensus.cc:493] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:41.891851  4356 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:41.911942  4356 raft_consensus.cc:515] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f613035d10864f9d875b502994a94a7d" member_type: VOTER }
I20260812 06:16:41.912153  4356 leader_election.cc:304] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [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: f613035d10864f9d875b502994a94a7d; no voters: 
I20260812 06:16:41.912415  4356 leader_election.cc:290] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:41.912563  4359 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:41.912768  4359 raft_consensus.cc:697] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 1 LEADER]: Becoming Leader. State: Replica: f613035d10864f9d875b502994a94a7d, State: Running, Role: LEADER
I20260812 06:16:41.912909  4356 sys_catalog.cc:565] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:41.912983  4359 consensus_queue.cc:237] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [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: "f613035d10864f9d875b502994a94a7d" member_type: VOTER }
I20260812 06:16:41.913431  4364 sys_catalog.cc:455] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f613035d10864f9d875b502994a94a7d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f613035d10864f9d875b502994a94a7d" member_type: VOTER } }
I20260812 06:16:41.913542  4364 sys_catalog.cc:458] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:41.913447  4367 sys_catalog.cc:455] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [sys.catalog]: SysCatalogTable state changed. Reason: New leader f613035d10864f9d875b502994a94a7d. Latest consensus state: current_term: 1 leader_uuid: "f613035d10864f9d875b502994a94a7d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f613035d10864f9d875b502994a94a7d" member_type: VOTER } }
I20260812 06:16:41.913861  4367 sys_catalog.cc:458] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:41.914290  4375 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:41.915093  4375 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:41.915343  3832 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:41.916956  4375 catalog_manager.cc:1383] Generated new cluster ID: b8dcae2044ce4a05ac1a10785f289f16
I20260812 06:16:41.917013  4375 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:41.929816  4375 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:41.930310  4375 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:41.938483  4375 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d: Generated new TSK 0
I20260812 06:16:41.938630  4375 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:41.947487  3832 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:41.949182  4402 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:16:41.949277  4405 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:16:41.949280  4400 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:16:41.949424  3832 server_base.cc:1061] running on GCE node
I20260812 06:16:41.949672  3832 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:41.949708  3832 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:16:41.949728  3832 hybrid_clock.cc:648] HybridClock initialized: now 1786515401949727 us; error 0 us; skew 500 ppm
I20260812 06:16:41.950513  3832 webserver.cc:533] Webserver started at http://127.3.190.1:37021/ using document root <none> and password file <none>
I20260812 06:16:41.950660  3832 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:41.950716  3832 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:41.950789  3832 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:41.951146  3832 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/instance:
uuid: "4ae9e509ba2247d5863da805aff7e8d5"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-gjw7"
I20260812 06:16:41.952500  3832 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:16:41.953359  4417 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:16:41.953601  3832 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:41.953677  3832 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root
uuid: "4ae9e509ba2247d5863da805aff7e8d5"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-gjw7"
I20260812 06:16:41.953745  3832 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-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:16:41.971097  3832 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:41.971438  3832 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:41.971720  3832 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:41.972210  3832 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:41.972249  3832 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.972285  3832 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:41.972314  3832 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.976339  3832 rpc_server.cc:307] RPC server started. Bound to: 127.3.190.1:32909
I20260812 06:16:41.976364  4557 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.190.1:32909 every 8 connection(s)
I20260812 06:16:41.980959  4559 heartbeater.cc:344] Connected to a master server at 127.3.190.62:44607
I20260812 06:16:41.981055  4559 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:41.981269  4559 heartbeater.cc:507] Master 127.3.190.62:44607 requested a full tablet report, sending...
I20260812 06:16:41.981906  4283 ts_manager.cc:194] Registered new tserver with Master: 4ae9e509ba2247d5863da805aff7e8d5 (127.3.190.1:32909)
I20260812 06:16:41.982250  3832 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005529445s
I20260812 06:16:41.982846  4283 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59840
I20260812 06:16:41.988680  4283 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59846:
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:16:41.996624  4472 tablet_service.cc:1511] Processing CreateTablet for tablet f0e6f9ad06c14747a18d2dff76f9c3c3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=931c554638ee48cd80ef729f4db0dbe0]), partition=
I20260812 06:16:41.996905  4472 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f0e6f9ad06c14747a18d2dff76f9c3c3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:41.998790  4587 tablet_bootstrap.cc:492] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Bootstrap starting.
I20260812 06:16:41.999750  4587 tablet_bootstrap.cc:654] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.000762  4587 tablet_bootstrap.cc:492] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: No bootstrap required, opened a new log
I20260812 06:16:42.000869  4587 ts_tablet_manager.cc:1403] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:42.001264  4587 raft_consensus.cc:359] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ae9e509ba2247d5863da805aff7e8d5" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 32909 } }
I20260812 06:16:42.001374  4587 raft_consensus.cc:385] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.001408  4587 raft_consensus.cc:740] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4ae9e509ba2247d5863da805aff7e8d5, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.001533  4587 consensus_queue.cc:260] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [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: "4ae9e509ba2247d5863da805aff7e8d5" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 32909 } }
I20260812 06:16:42.001600  4587 raft_consensus.cc:399] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.001638  4587 raft_consensus.cc:493] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.001684  4587 raft_consensus.cc:3060] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.014375  4587 raft_consensus.cc:515] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ae9e509ba2247d5863da805aff7e8d5" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 32909 } }
I20260812 06:16:42.014551  4587 leader_election.cc:304] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [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: 4ae9e509ba2247d5863da805aff7e8d5; no voters: 
I20260812 06:16:42.014775  4587 leader_election.cc:290] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.015008  4595 raft_consensus.cc:2804] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.015182  4587 ts_tablet_manager.cc:1434] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Time spent starting tablet: real 0.014s	user 0.003s	sys 0.000s
I20260812 06:16:42.015209  4595 raft_consensus.cc:697] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 1 LEADER]: Becoming Leader. State: Replica: 4ae9e509ba2247d5863da805aff7e8d5, State: Running, Role: LEADER
I20260812 06:16:42.015355  4559 heartbeater.cc:499] Master 127.3.190.62:44607 was elected leader, sending a full tablet report...
I20260812 06:16:42.015558  4595 consensus_queue.cc:237] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [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: "4ae9e509ba2247d5863da805aff7e8d5" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 32909 } }
I20260812 06:16:42.016948  4283 catalog_manager.cc:5719] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4ae9e509ba2247d5863da805aff7e8d5 (127.3.190.1). New cstate: current_term: 1 leader_uuid: "4ae9e509ba2247d5863da805aff7e8d5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ae9e509ba2247d5863da805aff7e8d5" member_type: VOTER last_known_addr { host: "127.3.190.1" port: 32909 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:42.076470  3832 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.023s	sys 0.000s
I20260812 06:16:42.227134  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushMRSOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=19.054940
I20260812 06:16:42.428260  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushMRSOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.201s	user 0.104s	sys 0.037s Metrics: {"bytes_written":12635686,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":93641,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33621,"lbm_writes_lt_1ms":765,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1408,"update_count":1540}
I20260812 06:16:42.428949  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3): free 20743880 bytes of WAL
I20260812 06:16:42.429189  4425 log_reader.cc:385] T f0e6f9ad06c14747a18d2dff76f9c3c3: removed 2 log segments from log reader
I20260812 06:16:42.429247  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000001 (ops 1-6)
I20260812 06:16:42.429306  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000002 (ops 7-11)
I20260812 06:16:42.432719  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:42.433226  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=9.134250
I20260812 06:16:42.526070  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.093s	user 0.016s	sys 0.009s Metrics: {"bytes_written":10953701,"delete_count":0,"lbm_write_time_us":10498,"lbm_writes_lt_1ms":270,"reinsert_count":0,"update_count":1335}
I20260812 06:16:42.526666  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=7.149875
I20260812 06:16:42.631722  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.105s	user 0.018s	sys 0.004s Metrics: {"bytes_written":9230686,"delete_count":0,"lbm_write_time_us":9617,"lbm_writes_lt_1ms":228,"reinsert_count":0,"update_count":1125}
I20260812 06:16:42.632331  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=7.149875
I20260812 06:16:42.734232  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.102s	user 0.012s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8715,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:42.734654  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=10.126437
I20260812 06:16:42.841082  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.106s	user 0.024s	sys 0.004s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":11732,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:42.841710  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=7.149875
I20260812 06:16:42.941496  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.100s	user 0.030s	sys 0.000s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":13239,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:42.941972  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling UndoDeltaBlockGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3): 16411395 bytes on disk
I20260812 06:16:42.942432  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: UndoDeltaBlockGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.942991  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=10.126437
I20260812 06:16:43.044750  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.102s	user 0.013s	sys 0.010s Metrics: {"bytes_written":11487010,"delete_count":0,"lbm_write_time_us":10418,"lbm_writes_lt_1ms":283,"reinsert_count":0,"update_count":1400}
I20260812 06:16:43.045359  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=7.149875
I20260812 06:16:43.147396  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.102s	user 0.006s	sys 0.021s Metrics: {"bytes_written":9025567,"delete_count":0,"lbm_write_time_us":11985,"lbm_writes_lt_1ms":223,"reinsert_count":0,"update_count":1100}
I20260812 06:16:43.147966  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=6.157687
I20260812 06:16:43.244153  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.096s	user 0.022s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9958,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.244722  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=10.126437
I20260812 06:16:43.346418  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.102s	user 0.030s	sys 0.004s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":15428,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:43.346915  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=7.149875
I20260812 06:16:43.447438  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.100s	user 0.011s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8360,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.447983  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=10.126437
I20260812 06:16:43.551994  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.104s	user 0.025s	sys 0.008s Metrics: {"bytes_written":11897250,"delete_count":0,"lbm_write_time_us":15048,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:43.552570  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=6.157687
I20260812 06:16:43.653151  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.100s	user 0.016s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8597,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.653723  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=8.142062
I20260812 06:16:43.758695  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.105s	user 0.010s	sys 0.019s Metrics: {"bytes_written":10338332,"delete_count":0,"lbm_write_time_us":11967,"lbm_writes_lt_1ms":255,"reinsert_count":0,"update_count":1260}
I20260812 06:16:43.759426  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=8.142062
I20260812 06:16:43.861519  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.102s	user 0.009s	sys 0.020s Metrics: {"bytes_written":10174244,"delete_count":0,"lbm_write_time_us":11978,"lbm_writes_lt_1ms":251,"reinsert_count":0,"update_count":1240}
I20260812 06:16:43.862186  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=9.134250
I20260812 06:16:43.966061  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.104s	user 0.024s	sys 0.006s Metrics: {"bytes_written":11035747,"delete_count":0,"lbm_write_time_us":12057,"lbm_writes_lt_1ms":272,"reinsert_count":0,"update_count":1345}
I20260812 06:16:43.966786  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=8.142062
I20260812 06:16:44.066819  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.100s	user 0.012s	sys 0.013s Metrics: {"bytes_written":9476830,"delete_count":0,"lbm_write_time_us":10996,"lbm_writes_lt_1ms":234,"reinsert_count":0,"update_count":1155}
I20260812 06:16:44.067442  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=7.149875
I20260812 06:16:44.167057  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.099s	user 0.013s	sys 0.005s Metrics: {"bytes_written":9107612,"delete_count":0,"lbm_write_time_us":7656,"lbm_writes_lt_1ms":225,"reinsert_count":0,"update_count":1110}
I20260812 06:16:44.167740  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=10.126437
I20260812 06:16:44.271059  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.103s	user 0.033s	sys 0.000s Metrics: {"bytes_written":11404967,"delete_count":0,"lbm_write_time_us":14668,"lbm_writes_lt_1ms":281,"reinsert_count":0,"update_count":1390}
I20260812 06:16:44.271821  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=8.142062
I20260812 06:16:44.371644  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.100s	user 0.019s	sys 0.006s Metrics: {"bytes_written":9722971,"delete_count":0,"lbm_write_time_us":10118,"lbm_writes_lt_1ms":240,"reinsert_count":0,"update_count":1185}
I20260812 06:16:44.372166  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=9.134250
I20260812 06:16:44.402068  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.030s	user 0.010s	sys 0.016s Metrics: {"bytes_written":10789607,"delete_count":0,"lbm_write_time_us":11384,"lbm_writes_lt_1ms":266,"reinsert_count":0,"update_count":1315}
I20260812 06:16:44.402685  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushMRSOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=1.195565
I20260812 06:16:44.456466  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushMRSOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.054s	user 0.030s	sys 0.004s Metrics: {"bytes_written":2177088,"cfile_init":1,"dirs.queue_time_us":190,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":10239,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2791,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":53,"thread_start_us":101,"threads_started":1}
I20260812 06:16:44.457233  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3): free 212460761 bytes of WAL
I20260812 06:16:44.457520  4425 log_reader.cc:385] T f0e6f9ad06c14747a18d2dff76f9c3c3: removed 21 log segments from log reader
I20260812 06:16:44.457569  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000003 (ops 12-16)
I20260812 06:16:44.457607  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000004 (ops 17-20)
I20260812 06:16:44.457640  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000005 (ops 21-25)
I20260812 06:16:44.457670  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000006 (ops 26-30)
I20260812 06:16:44.457700  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000007 (ops 31-35)
I20260812 06:16:44.457731  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000008 (ops 36-40)
I20260812 06:16:44.457757  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000009 (ops 41-45)
I20260812 06:16:44.457787  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000010 (ops 46-50)
I20260812 06:16:44.457839  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000011 (ops 51-55)
I20260812 06:16:44.457868  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000012 (ops 56-60)
I20260812 06:16:44.457898  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000013 (ops 61-65)
I20260812 06:16:44.457928  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000014 (ops 66-70)
I20260812 06:16:44.457957  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000015 (ops 71-74)
I20260812 06:16:44.457988  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000016 (ops 75-79)
I20260812 06:16:44.458014  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000017 (ops 80-84)
I20260812 06:16:44.458045  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000018 (ops 85-89)
I20260812 06:16:44.458073  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000019 (ops 90-94)
I20260812 06:16:44.458103  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000020 (ops 95-99)
I20260812 06:16:44.458132  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000021 (ops 100-104)
I20260812 06:16:44.458163  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000022 (ops 105-109)
I20260812 06:16:44.458191  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000023 (ops 110-114)
I20260812 06:16:44.495559  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.038s	user 0.000s	sys 0.036s Metrics: {}
I20260812 06:16:44.495985  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=10.126437
I20260812 06:16:44.537964  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.042s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13604,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.538388  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3): free 11564875 bytes of WAL
I20260812 06:16:44.538582  4425 log_reader.cc:385] T f0e6f9ad06c14747a18d2dff76f9c3c3: removed 1 log segments from log reader
I20260812 06:16:44.538650  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000024 (ops 115-118)
I20260812 06:16:44.541115  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:44.541468  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling UndoDeltaBlockGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3): 733 bytes on disk
I20260812 06:16:44.541834  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: UndoDeltaBlockGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3) 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:16:44.542244  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=2.188937
I20260812 06:16:44.552774  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.553184  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling MajorDeltaCompactionOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=1.000000
I20260812 06:16:45.927340  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: MajorDeltaCompactionOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 1.374s	user 0.801s	sys 0.572s Metrics: {"cfile_cache_miss":5653,"cfile_cache_miss_bytes":234000296,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":23,"delta_iterators_relevant":23,"dirs.queue_time_us":1432,"lbm_read_time_us":91782,"lbm_reads_lt_1ms":5689,"lbm_write_time_us":251260,"lbm_writes_lt_1ms":5647,"peak_mem_usage":696871072,"reinsert_count":0,"spinlock_wait_cycles":42880,"thread_start_us":627,"threads_started":7,"update_count":28000}
I20260812 06:16:45.928007  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=97.438937
I20260812 06:16:46.226007  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.298s	user 0.164s	sys 0.120s Metrics: {"bytes_written":102560590,"delete_count":0,"lbm_write_time_us":127420,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":2503,"reinsert_count":0,"update_count":12500}
I20260812 06:16:46.226833  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=21.040500
I20260812 06:16:46.412734  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.186s	user 0.029s	sys 0.018s Metrics: {"bytes_written":22973760,"delete_count":0,"lbm_write_time_us":22215,"lbm_writes_lt_1ms":563,"reinsert_count":0,"update_count":2800}
I20260812 06:16:46.413345  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=16.079562
I20260812 06:16:46.599694  3832 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.523s	user 1.603s	sys 0.098s
I20260812 06:16:46.616613  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.203s	user 0.026s	sys 0.013s Metrics: {"bytes_written":18050872,"delete_count":0,"lbm_write_time_us":17845,"lbm_writes_lt_1ms":443,"reinsert_count":0,"update_count":2200}
I20260812 06:16:46.617342  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=18.063937
I20260812 06:16:46.776662  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushDeltaMemStoresOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.159s	user 0.041s	sys 0.017s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26263,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:16:46.777344  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling FlushMRSOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=1.000000
I20260812 06:16:46.843124  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: FlushMRSOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.066s	user 0.031s	sys 0.014s Metrics: {"bytes_written":1767313,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1398,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":25299,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":43,"peak_mem_usage":0,"rows_written":43}
I20260812 06:16:46.843757  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3): free 133477658 bytes of WAL
I20260812 06:16:46.843993  4425 log_reader.cc:385] T f0e6f9ad06c14747a18d2dff76f9c3c3: removed 13 log segments from log reader
I20260812 06:16:46.844048  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000025 (ops 119-123)
I20260812 06:16:46.844090  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000026 (ops 124-128)
I20260812 06:16:46.844121  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000027 (ops 129-133)
I20260812 06:16:46.844151  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000028 (ops 134-138)
I20260812 06:16:46.844177  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000029 (ops 139-143)
I20260812 06:16:46.844214  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000030 (ops 144-148)
I20260812 06:16:46.844244  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000031 (ops 149-153)
I20260812 06:16:46.844272  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000032 (ops 154-158)
I20260812 06:16:46.844301  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000033 (ops 159-163)
I20260812 06:16:46.844329  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000034 (ops 164-168)
I20260812 06:16:46.844358  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000035 (ops 169-173)
I20260812 06:16:46.844386  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000036 (ops 174-178)
I20260812 06:16:46.844414  4425 log.cc:1079] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: Deleting log segment in path: /tmp/dist-test-task3ZxAGt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515396910768-3832-0/minicluster-data/ts-0-root/wals/f0e6f9ad06c14747a18d2dff76f9c3c3/wal-000000037 (ops 179-183)
I20260812 06:16:46.873426  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: LogGCOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:46.873903  4560 maintenance_manager.cc:419] P 4ae9e509ba2247d5863da805aff7e8d5: Scheduling MajorDeltaCompactionOp(f0e6f9ad06c14747a18d2dff76f9c3c3): perf score=1.000000
I20260812 06:16:46.920346  3832 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.320s	user 0.001s	sys 0.000s
I20260812 06:16:46.920830  3832 tablet_server.cc:179] TabletServer@127.3.190.1:0 shutting down...
I20260812 06:16:47.645534  4425 maintenance_manager.cc:643] P 4ae9e509ba2247d5863da805aff7e8d5: MajorDeltaCompactionOp(f0e6f9ad06c14747a18d2dff76f9c3c3) complete. Timing: real 0.771s	user 0.476s	sys 0.293s Metrics: {"cfile_cache_hit":2122,"cfile_cache_hit_bytes":90029678,"cfile_cache_miss":1914,"cfile_cache_miss_bytes":78329717,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1328,"lbm_read_time_us":30069,"lbm_reads_lt_1ms":1930,"lbm_write_time_us":139670,"lbm_writes_lt_1ms":4046,"mutex_wait_us":42,"peak_mem_usage":498045920,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":351,"threads_started":6,"update_count":20000}
I20260812 06:16:47.646145  3832 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:47.646365  3832 tablet_replica.cc:333] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5: stopping tablet replica
I20260812 06:16:47.646507  3832 raft_consensus.cc:2243] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.646674  3832 raft_consensus.cc:2272] T f0e6f9ad06c14747a18d2dff76f9c3c3 P 4ae9e509ba2247d5863da805aff7e8d5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.659629  3832 tablet_server.cc:196] TabletServer@127.3.190.1:0 shutdown complete.
I20260812 06:16:48.254254  3832 master.cc:562] Master@127.3.190.62:44607 shutting down...
I20260812 06:16:48.257324  3832 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:48.257493  3832 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:48.257545  3832 tablet_replica.cc:333] T 00000000000000000000000000000000 P f613035d10864f9d875b502994a94a7d: stopping tablet replica
I20260812 06:16:48.270102  3832 master.cc:584] Master@127.3.190.62:44607 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6487 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11420 ms total)

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