[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:19.556066   854 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.213.190:33929
I20260812 06:17:19.557180   854 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:19.557811   854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:19.564436   862 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:19.564479   854 server_base.cc:1061] running on GCE node
W20260812 06:17:19.564502   867 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:19.564683   863 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:19.565183   854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:19.565290   854 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:19.565335   854 hybrid_clock.cc:648] HybridClock initialized: now 1786515439565331 us; error 0 us; skew 500 ppm
I20260812 06:17:19.567130   854 webserver.cc:533] Webserver started at http://127.0.213.190:44715/ using document root <none> and password file <none>
I20260812 06:17:19.567724   854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:19.567793   854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:19.568051   854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:19.569757   854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/master-0-root/instance:
uuid: "bee639b3d0824ec99838f7e77765690c"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-lkx2"
I20260812 06:17:19.573287   854 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:17:19.575350   875 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.576334   854 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:19.576474   854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/master-0-root
uuid: "bee639b3d0824ec99838f7e77765690c"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-lkx2"
I20260812 06:17:19.576573   854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:19.587019   854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:19.587646   854 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:19.587802   854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:19.595321   854 rpc_server.cc:307] RPC server started. Bound to: 127.0.213.190:33929
I20260812 06:17:19.595325   963 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.213.190:33929 every 8 connection(s)
I20260812 06:17:19.597695   964 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:19.603330   964 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c: Bootstrap starting.
I20260812 06:17:19.605820   964 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:19.606781   964 log.cc:826] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:19.608590   964 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c: No bootstrap required, opened a new log
I20260812 06:17:19.611488   964 raft_consensus.cc:359] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bee639b3d0824ec99838f7e77765690c" member_type: VOTER }
I20260812 06:17:19.611668   964 raft_consensus.cc:385] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:19.611745   964 raft_consensus.cc:740] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bee639b3d0824ec99838f7e77765690c, State: Initialized, Role: FOLLOWER
I20260812 06:17:19.612449   964 consensus_queue.cc:260] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [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: "bee639b3d0824ec99838f7e77765690c" member_type: VOTER }
I20260812 06:17:19.612617   964 raft_consensus.cc:399] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:19.612687   964 raft_consensus.cc:493] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:19.612818   964 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:19.613652   964 raft_consensus.cc:515] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bee639b3d0824ec99838f7e77765690c" member_type: VOTER }
I20260812 06:17:19.614116   964 leader_election.cc:304] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [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: bee639b3d0824ec99838f7e77765690c; no voters: 
I20260812 06:17:19.614466   964 leader_election.cc:290] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:19.614555   970 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:19.614792   970 raft_consensus.cc:697] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 1 LEADER]: Becoming Leader. State: Replica: bee639b3d0824ec99838f7e77765690c, State: Running, Role: LEADER
I20260812 06:17:19.615235   970 consensus_queue.cc:237] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [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: "bee639b3d0824ec99838f7e77765690c" member_type: VOTER }
I20260812 06:17:19.615543   964 sys_catalog.cc:565] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:19.617247   973 sys_catalog.cc:455] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bee639b3d0824ec99838f7e77765690c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bee639b3d0824ec99838f7e77765690c" member_type: VOTER } }
I20260812 06:17:19.617291   978 sys_catalog.cc:455] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [sys.catalog]: SysCatalogTable state changed. Reason: New leader bee639b3d0824ec99838f7e77765690c. Latest consensus state: current_term: 1 leader_uuid: "bee639b3d0824ec99838f7e77765690c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bee639b3d0824ec99838f7e77765690c" member_type: VOTER } }
I20260812 06:17:19.617372   973 sys_catalog.cc:458] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:19.617391   978 sys_catalog.cc:458] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:19.617848   854 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:19.619771  1002 catalog_manager.cc:1594] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:19.619834  1002 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:19.619912   998 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:19.620733   998 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:19.625537   998 catalog_manager.cc:1383] Generated new cluster ID: 2e16ec51c73945f78d72a586c99a2529
I20260812 06:17:19.625608   998 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:19.643026   998 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:19.644269   998 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:19.656241   998 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c: Generated new TSK 0
I20260812 06:17:19.656946   998 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:19.682641   854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:19.685352  1006 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:19.685465  1016 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:19.685632   854 server_base.cc:1061] running on GCE node
W20260812 06:17:19.685719  1009 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:19.685976   854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:19.686021   854 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:19.686041   854 hybrid_clock.cc:648] HybridClock initialized: now 1786515439686041 us; error 0 us; skew 500 ppm
I20260812 06:17:19.686991   854 webserver.cc:533] Webserver started at http://127.0.213.129:39897/ using document root <none> and password file <none>
I20260812 06:17:19.687160   854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:19.687211   854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:19.687289   854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:19.687670   854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/instance:
uuid: "0c58dcd84c7f498f870a48ff37376d8b"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-lkx2"
I20260812 06:17:19.689232   854 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:17:19.690184  1025 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.690447   854 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:19.690521   854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root
uuid: "0c58dcd84c7f498f870a48ff37376d8b"
format_stamp: "Formatted at 2026-08-12 06:17:19 on dist-test-slave-lkx2"
I20260812 06:17:19.690593   854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:19.708510   854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:19.709396   854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:19.709939   854 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:19.710851   854 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:19.710930   854 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.711000   854 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:19.711030   854 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:19.717126   854 rpc_server.cc:307] RPC server started. Bound to: 127.0.213.129:42241
I20260812 06:17:19.717296  1134 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.213.129:42241 every 8 connection(s)
I20260812 06:17:19.727159  1135 heartbeater.cc:344] Connected to a master server at 127.0.213.190:33929
I20260812 06:17:19.727422  1135 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:19.727867  1135 heartbeater.cc:507] Master 127.0.213.190:33929 requested a full tablet report, sending...
I20260812 06:17:19.729338   908 ts_manager.cc:194] Registered new tserver with Master: 0c58dcd84c7f498f870a48ff37376d8b (127.0.213.129:42241)
I20260812 06:17:19.730178   854 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012323877s
I20260812 06:17:19.730515   908 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43814
I20260812 06:17:19.739948   908 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43824:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:19.753841  1075 tablet_service.cc:1511] Processing CreateTablet for tablet e46887e7c7ed4352bcc48a56593aaf9a (DEFAULT_TABLE table=heavy-update-compaction-test [id=a866a56a6a614554a6907370d0c673b3]), partition=
I20260812 06:17:19.754392  1075 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e46887e7c7ed4352bcc48a56593aaf9a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:19.757432  1159 tablet_bootstrap.cc:492] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Bootstrap starting.
I20260812 06:17:19.758628  1159 tablet_bootstrap.cc:654] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:19.760164  1159 tablet_bootstrap.cc:492] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: No bootstrap required, opened a new log
I20260812 06:17:19.760324  1159 ts_tablet_manager.cc:1403] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:19.760841  1159 raft_consensus.cc:359] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c58dcd84c7f498f870a48ff37376d8b" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 42241 } }
I20260812 06:17:19.760955  1159 raft_consensus.cc:385] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:19.760989  1159 raft_consensus.cc:740] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0c58dcd84c7f498f870a48ff37376d8b, State: Initialized, Role: FOLLOWER
I20260812 06:17:19.761124  1159 consensus_queue.cc:260] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [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: "0c58dcd84c7f498f870a48ff37376d8b" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 42241 } }
I20260812 06:17:19.761200  1159 raft_consensus.cc:399] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:19.761245  1159 raft_consensus.cc:493] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:19.761292  1159 raft_consensus.cc:3060] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:19.762176  1159 raft_consensus.cc:515] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c58dcd84c7f498f870a48ff37376d8b" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 42241 } }
I20260812 06:17:19.762319  1159 leader_election.cc:304] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [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: 0c58dcd84c7f498f870a48ff37376d8b; no voters: 
I20260812 06:17:19.762528  1159 leader_election.cc:290] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:19.762650  1163 raft_consensus.cc:2804] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:19.762826  1163 raft_consensus.cc:697] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 1 LEADER]: Becoming Leader. State: Replica: 0c58dcd84c7f498f870a48ff37376d8b, State: Running, Role: LEADER
I20260812 06:17:19.762893  1159 ts_tablet_manager.cc:1434] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:19.763258  1135 heartbeater.cc:499] Master 127.0.213.190:33929 was elected leader, sending a full tablet report...
I20260812 06:17:19.763589  1163 consensus_queue.cc:237] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [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: "0c58dcd84c7f498f870a48ff37376d8b" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 42241 } }
I20260812 06:17:19.766836   908 catalog_manager.cc:5719] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b reported cstate change: term changed from 0 to 1, leader changed from <none> to 0c58dcd84c7f498f870a48ff37376d8b (127.0.213.129). New cstate: current_term: 1 leader_uuid: "0c58dcd84c7f498f870a48ff37376d8b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c58dcd84c7f498f870a48ff37376d8b" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 42241 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:19.830904   854 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.028s	sys 0.000s
I20260812 06:17:19.968294  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=19.054940
I20260812 06:17:20.113029  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.144s	user 0.111s	sys 0.032s Metrics: {"bytes_written":8943515,"cfile_init":1,"compiler_manager_pool.queue_time_us":212,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1042,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36007,"lbm_writes_lt_1ms":675,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":281984,"thread_start_us":131,"threads_started":1,"update_count":1090}
I20260812 06:17:20.114091  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a): free 20743880 bytes of WAL
I20260812 06:17:20.114398  1035 log_reader.cc:385] T e46887e7c7ed4352bcc48a56593aaf9a: removed 2 log segments from log reader
I20260812 06:17:20.114454  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000001 (ops 1-6)
I20260812 06:17:20.114516  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000002 (ops 7-11)
I20260812 06:17:20.118500  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:20.118817  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:20.134262  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:17:20.134857  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:20.254683  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.120s	user 0.093s	sys 0.016s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569848,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":528,"lbm_read_time_us":8315,"lbm_reads_lt_1ms":364,"lbm_write_time_us":18770,"lbm_writes_lt_1ms":343,"mutex_wait_us":58,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":300,"threads_started":5,"update_count":1500}
I20260812 06:17:20.255295  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a): 16411393 bytes on disk
I20260812 06:17:20.255872  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.256449  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:20.302012  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.045s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17109,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.302465  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:20.313815  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.314354  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:20.430388  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.116s	user 0.091s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":674,"lbm_read_time_us":9114,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21626,"lbm_writes_lt_1ms":443,"mutex_wait_us":350,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":73472,"update_count":2000}
I20260812 06:17:20.430892  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:20.480882  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.050s	user 0.036s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15919,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.481451  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:20.492170  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.492746  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:20.645783  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.153s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":11856,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26044,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.646498  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:20.691428  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.045s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17104,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.691998  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:20.707671  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.708242  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:20.829674  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.121s	user 0.098s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":8359,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24681,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:20.830191  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:20.872191  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.042s	user 0.016s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.872740  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:20.882928  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.883430  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:21.003286  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.120s	user 0.115s	sys 0.004s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":825,"lbm_read_time_us":8892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21524,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:17:21.003769  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:21.048658  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.045s	user 0.009s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14541,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.049226  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:21.059693  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3963,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.060156  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:21.204216  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.144s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":10388,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24401,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.204860  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:21.254864  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.050s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17418,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.255442  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:21.271512  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.016s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.272049  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:21.399870  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":10042,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23740,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:21.400857  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:21.443620  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.043s	user 0.009s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16188,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.444196  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:21.455224  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.456075  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:21.486033  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1270,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1848,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:21.486979  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a): free 121006436 bytes of WAL
I20260812 06:17:21.487233  1035 log_reader.cc:385] T e46887e7c7ed4352bcc48a56593aaf9a: removed 12 log segments from log reader
I20260812 06:17:21.487294  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000003 (ops 12-16)
I20260812 06:17:21.487341  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000004 (ops 17-20)
I20260812 06:17:21.487376  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000005 (ops 21-25)
I20260812 06:17:21.487404  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000006 (ops 26-30)
I20260812 06:17:21.487442  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000007 (ops 31-35)
I20260812 06:17:21.487469  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000008 (ops 36-40)
I20260812 06:17:21.487500  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000009 (ops 41-45)
I20260812 06:17:21.487532  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000010 (ops 46-50)
I20260812 06:17:21.487561  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000011 (ops 51-55)
I20260812 06:17:21.487589  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000012 (ops 56-60)
I20260812 06:17:21.487617  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000013 (ops 61-65)
I20260812 06:17:21.487646  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000014 (ops 66-70)
I20260812 06:17:21.513712  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:21.514209  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=3.181125
I20260812 06:17:21.531466  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6924,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:21.531889  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a): 483 bytes on disk
I20260812 06:17:21.532291  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a) 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:17:21.532752  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:21.542385  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3360,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.542955  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:21.722029  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.179s	user 0.149s	sys 0.020s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":999,"lbm_read_time_us":12277,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38449,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":111,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20992,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:17:21.722566  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:21.774178  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.051s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21836,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.774691  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:21.787256  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4623,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.787876  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:21.947314  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.158s	user 0.126s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":121,"lbm_read_time_us":10587,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30518,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:17:21.947863  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:21.998390  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.050s	user 0.041s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23469,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.999037  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:22.015878  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.016510  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:22.183983  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.167s	user 0.111s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":10899,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31626,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:22.184585  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:22.237483  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.053s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24985,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.238049  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:22.254088  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.255343  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:22.428715  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.173s	user 0.127s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":868,"lbm_read_time_us":13135,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29721,"lbm_writes_lt_1ms":543,"mutex_wait_us":421,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:22.429342  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:22.493907  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.064s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24020,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.494406  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:22.504801  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.505306  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:22.676520  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.171s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":996,"lbm_read_time_us":13237,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29410,"lbm_writes_lt_1ms":543,"mutex_wait_us":333,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:22.677173  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:22.730487  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.053s	user 0.021s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.731076  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:22.742660  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.743124  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:22.919921  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.177s	user 0.131s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4891,"dirs.run_cpu_time_us":1766,"dirs.run_wall_time_us":9100,"lbm_read_time_us":12570,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29313,"lbm_writes_lt_1ms":543,"mutex_wait_us":4270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:17:22.920629  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:22.971518  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.051s	user 0.015s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17928,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.972115  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:22.986902  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.987396  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:23.027722  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.040s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1546,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:23.028699  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a): free 136728203 bytes of WAL
I20260812 06:17:23.028954  1035 log_reader.cc:385] T e46887e7c7ed4352bcc48a56593aaf9a: removed 13 log segments from log reader
I20260812 06:17:23.029004  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000015 (ops 71-75)
I20260812 06:17:23.029047  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000016 (ops 76-80)
I20260812 06:17:23.029081  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000017 (ops 81-85)
I20260812 06:17:23.029112  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000018 (ops 86-90)
I20260812 06:17:23.029143  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000019 (ops 91-95)
I20260812 06:17:23.029173  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000020 (ops 96-100)
I20260812 06:17:23.029204  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000021 (ops 101-105)
I20260812 06:17:23.029233  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000022 (ops 106-110)
I20260812 06:17:23.029263  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000023 (ops 111-115)
I20260812 06:17:23.029294  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000024 (ops 116-120)
I20260812 06:17:23.029323  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000025 (ops 121-125)
I20260812 06:17:23.029354  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000026 (ops 126-130)
I20260812 06:17:23.029383  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000027 (ops 131-135)
I20260812 06:17:23.056979  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:23.057454  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a): 492 bytes on disk
I20260812 06:17:23.057950  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:17:23.058633  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=3.181125
I20260812 06:17:23.070398  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4553933,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:23.070891  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:23.080374  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3389,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:23.080897  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:23.315964  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.235s	user 0.167s	sys 0.051s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":550,"lbm_read_time_us":16436,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37726,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":119,"threads_started":2,"update_count":3500}
I20260812 06:17:23.316602  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=18.063937
I20260812 06:17:23.378866  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.062s	user 0.048s	sys 0.005s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":25313,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:23.379362  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:23.390744  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.391247  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:23.568667  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.177s	user 0.120s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1199,"lbm_read_time_us":13941,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29510,"lbm_writes_lt_1ms":643,"mutex_wait_us":399,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:23.569228  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:23.609503  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.040s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16964,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.610342  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:23.625515  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.626123  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:23.775519  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.149s	user 0.098s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":435,"lbm_read_time_us":8410,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26674,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":201472,"update_count":2500}
I20260812 06:17:23.776181  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:23.821847  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.045s	user 0.017s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19981,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.822398  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:23.962265  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.140s	user 0.099s	sys 0.038s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":947,"lbm_read_time_us":8781,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23785,"lbm_writes_lt_1ms":443,"mutex_wait_us":351,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:23.962837  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=11.118625
I20260812 06:17:23.993916  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.031s	user 0.021s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13169,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:23.994446  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:24.018329  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.024s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.018929  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:24.029194  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.029831  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:24.212142  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.182s	user 0.130s	sys 0.042s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":161,"lbm_read_time_us":10228,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28609,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:24.212743  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=14.095187
I20260812 06:17:24.260202  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.047s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17103,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.260779  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:24.272025  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.272746  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:24.428762  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.156s	user 0.127s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":120,"lbm_read_time_us":10643,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30060,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":46592,"update_count":2500}
I20260812 06:17:24.429342  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=10.126437
I20260812 06:17:24.468120  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.039s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16751,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.468770  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:24.479272  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.479939  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:24.513091  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushMRSOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1505,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1483,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:24.513792  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a): free 128867776 bytes of WAL
I20260812 06:17:24.514034  1035 log_reader.cc:385] T e46887e7c7ed4352bcc48a56593aaf9a: removed 13 log segments from log reader
I20260812 06:17:24.514076  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000028 (ops 136-140)
I20260812 06:17:24.514106  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000029 (ops 141-144)
I20260812 06:17:24.514139  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000030 (ops 145-149)
I20260812 06:17:24.514173  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000031 (ops 150-154)
I20260812 06:17:24.514199  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000032 (ops 155-159)
I20260812 06:17:24.514228  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000033 (ops 160-164)
I20260812 06:17:24.514261  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000034 (ops 165-169)
I20260812 06:17:24.514293  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000035 (ops 170-174)
I20260812 06:17:24.514328  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000036 (ops 175-178)
I20260812 06:17:24.514360  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000037 (ops 179-183)
I20260812 06:17:24.514392  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000038 (ops 184-188)
I20260812 06:17:24.514424  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000039 (ops 189-192)
I20260812 06:17:24.514456  1035 log.cc:1079] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515439544724-854-0/minicluster-data/ts-0-root/wals/e46887e7c7ed4352bcc48a56593aaf9a/wal-000000040 (ops 193-197)
I20260812 06:17:24.539156  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: LogGCOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:24.539574  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a): 483 bytes on disk
I20260812 06:17:24.540009  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: UndoDeltaBlockGCOp(e46887e7c7ed4352bcc48a56593aaf9a) 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:17:24.540613  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=3.181125
I20260812 06:17:24.548923   854 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.718s	user 1.702s	sys 0.141s
I20260812 06:17:24.552482  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:24.552930  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=2.188937
I20260812 06:17:24.567562  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: FlushDeltaMemStoresOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5585,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.568202  1137 maintenance_manager.cc:419] P 0c58dcd84c7f498f870a48ff37376d8b: Scheduling MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a): perf score=1.000000
I20260812 06:17:24.616320   854 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.001s	sys 0.000s
I20260812 06:17:24.617084   854 tablet_server.cc:179] TabletServer@127.0.213.129:0 shutting down...
I20260812 06:17:24.704941  1035 maintenance_manager.cc:643] P 0c58dcd84c7f498f870a48ff37376d8b: MajorDeltaCompactionOp(e46887e7c7ed4352bcc48a56593aaf9a) complete. Timing: real 0.136s	user 0.106s	sys 0.030s Metrics: {"cfile_cache_hit":352,"cfile_cache_hit_bytes":14319891,"cfile_cache_miss":282,"cfile_cache_miss_bytes":14557438,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":555,"lbm_read_time_us":6902,"lbm_reads_lt_1ms":314,"lbm_write_time_us":27953,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":115584,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:17:24.706131   854 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:24.706648   854 tablet_replica.cc:333] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b: stopping tablet replica
I20260812 06:17:24.706911   854 raft_consensus.cc:2243] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:24.707170   854 raft_consensus.cc:2272] T e46887e7c7ed4352bcc48a56593aaf9a P 0c58dcd84c7f498f870a48ff37376d8b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:24.722638   854 tablet_server.cc:196] TabletServer@127.0.213.129:0 shutdown complete.
I20260812 06:17:24.759451   854 master.cc:562] Master@127.0.213.190:33929 shutting down...
I20260812 06:17:24.762724   854 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:24.762910   854 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:24.762993   854 tablet_replica.cc:333] T 00000000000000000000000000000000 P bee639b3d0824ec99838f7e77765690c: stopping tablet replica
I20260812 06:17:24.775406   854 master.cc:584] Master@127.0.213.190:33929 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5303 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:24.859064   854 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.213.190:36495
I20260812 06:17:24.859450   854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.861511  1199 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.861526  1191 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.861577  1196 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.861546   854 server_base.cc:1061] running on GCE node
I20260812 06:17:24.861896   854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.861948   854 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:24.861961   854 hybrid_clock.cc:648] HybridClock initialized: now 1786515444861961 us; error 0 us; skew 500 ppm
I20260812 06:17:24.862763   854 webserver.cc:533] Webserver started at http://127.0.213.190:41845/ using document root <none> and password file <none>
I20260812 06:17:24.862914   854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.862960   854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.863036   854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.863400   854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/master-0-root/instance:
uuid: "966d841d9ec242a0bfd38653b93d6092"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-lkx2"
I20260812 06:17:24.864914   854 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:24.865813  1211 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.866032   854 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:24.866098   854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/master-0-root
uuid: "966d841d9ec242a0bfd38653b93d6092"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-lkx2"
I20260812 06:17:24.866168   854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.881791   854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.882149   854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.886227   854 rpc_server.cc:307] RPC server started. Bound to: 127.0.213.190:36495
I20260812 06:17:24.899766  1302 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.213.190:36495 every 8 connection(s)
I20260812 06:17:24.899786  1303 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.901829  1303 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092: Bootstrap starting.
I20260812 06:17:24.902645  1303 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.903656  1303 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092: No bootstrap required, opened a new log
I20260812 06:17:24.904031  1303 raft_consensus.cc:359] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "966d841d9ec242a0bfd38653b93d6092" member_type: VOTER }
I20260812 06:17:24.904116  1303 raft_consensus.cc:385] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.904143  1303 raft_consensus.cc:740] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 966d841d9ec242a0bfd38653b93d6092, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.904260  1303 consensus_queue.cc:260] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [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: "966d841d9ec242a0bfd38653b93d6092" member_type: VOTER }
I20260812 06:17:24.904317  1303 raft_consensus.cc:399] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.904368  1303 raft_consensus.cc:493] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.904419  1303 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.905045  1303 raft_consensus.cc:515] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "966d841d9ec242a0bfd38653b93d6092" member_type: VOTER }
I20260812 06:17:24.905165  1303 leader_election.cc:304] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [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: 966d841d9ec242a0bfd38653b93d6092; no voters: 
I20260812 06:17:24.905326  1303 leader_election.cc:290] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.905458  1308 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.905668  1308 raft_consensus.cc:697] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 1 LEADER]: Becoming Leader. State: Replica: 966d841d9ec242a0bfd38653b93d6092, State: Running, Role: LEADER
I20260812 06:17:24.905812  1303 sys_catalog.cc:565] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:24.905813  1308 consensus_queue.cc:237] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [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: "966d841d9ec242a0bfd38653b93d6092" member_type: VOTER }
I20260812 06:17:24.906280  1313 sys_catalog.cc:455] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 966d841d9ec242a0bfd38653b93d6092. Latest consensus state: current_term: 1 leader_uuid: "966d841d9ec242a0bfd38653b93d6092" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "966d841d9ec242a0bfd38653b93d6092" member_type: VOTER } }
I20260812 06:17:24.906275  1311 sys_catalog.cc:455] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "966d841d9ec242a0bfd38653b93d6092" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "966d841d9ec242a0bfd38653b93d6092" member_type: VOTER } }
I20260812 06:17:24.906425  1313 sys_catalog.cc:458] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.906471  1311 sys_catalog.cc:458] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.907081  1320 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:24.907859  1320 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:24.908027   854 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:24.909694  1320 catalog_manager.cc:1383] Generated new cluster ID: aa624d46ea6348f6acdd4766ff26855c
I20260812 06:17:24.909752  1320 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:24.925482  1320 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:24.926077  1320 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:24.934458  1320 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092: Generated new TSK 0
I20260812 06:17:24.934644  1320 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:24.940614   854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.942576  1342 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.942698  1350 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.942763   854 server_base.cc:1061] running on GCE node
W20260812 06:17:24.942811  1343 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.943089   854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.943136   854 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:24.943151   854 hybrid_clock.cc:648] HybridClock initialized: now 1786515444943151 us; error 0 us; skew 500 ppm
I20260812 06:17:24.944085   854 webserver.cc:533] Webserver started at http://127.0.213.129:43785/ using document root <none> and password file <none>
I20260812 06:17:24.944242   854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.944291   854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.944396   854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.944816   854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/instance:
uuid: "b01b9a2a5700427cb97deecad035297a"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-lkx2"
I20260812 06:17:24.946275   854 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:24.947173  1356 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.947379   854 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:24.947445   854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root
uuid: "b01b9a2a5700427cb97deecad035297a"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-lkx2"
I20260812 06:17:24.947525   854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.958098   854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.958482   854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.958794   854 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:24.959264   854 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:24.959302   854 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.959337   854 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:24.959367   854 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.963554   854 rpc_server.cc:307] RPC server started. Bound to: 127.0.213.129:38115
I20260812 06:17:24.963574  1458 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.213.129:38115 every 8 connection(s)
I20260812 06:17:24.968502  1459 heartbeater.cc:344] Connected to a master server at 127.0.213.190:36495
I20260812 06:17:24.968613  1459 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:24.968849  1459 heartbeater.cc:507] Master 127.0.213.190:36495 requested a full tablet report, sending...
I20260812 06:17:24.969547  1244 ts_manager.cc:194] Registered new tserver with Master: b01b9a2a5700427cb97deecad035297a (127.0.213.129:38115)
I20260812 06:17:24.969758   854 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005804339s
I20260812 06:17:24.970312  1244 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58838
I20260812 06:17:24.977041  1244 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58848:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:24.985661  1398 tablet_service.cc:1511] Processing CreateTablet for tablet 395e4546297a47409fa74a012ff0a5d9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d5c2aa6f1de14a2fbdff85b7981b9dfc]), partition=
I20260812 06:17:24.985930  1398 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 395e4546297a47409fa74a012ff0a5d9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.987952  1482 tablet_bootstrap.cc:492] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Bootstrap starting.
I20260812 06:17:24.988894  1482 tablet_bootstrap.cc:654] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.989893  1482 tablet_bootstrap.cc:492] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: No bootstrap required, opened a new log
I20260812 06:17:24.989969  1482 ts_tablet_manager.cc:1403] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:24.990391  1482 raft_consensus.cc:359] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b01b9a2a5700427cb97deecad035297a" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 38115 } }
I20260812 06:17:24.990489  1482 raft_consensus.cc:385] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.990530  1482 raft_consensus.cc:740] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b01b9a2a5700427cb97deecad035297a, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.990665  1482 consensus_queue.cc:260] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [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: "b01b9a2a5700427cb97deecad035297a" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 38115 } }
I20260812 06:17:24.990751  1482 raft_consensus.cc:399] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.990784  1482 raft_consensus.cc:493] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.990832  1482 raft_consensus.cc:3060] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.991618  1482 raft_consensus.cc:515] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b01b9a2a5700427cb97deecad035297a" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 38115 } }
I20260812 06:17:24.991766  1482 leader_election.cc:304] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [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: b01b9a2a5700427cb97deecad035297a; no voters: 
I20260812 06:17:24.991955  1482 leader_election.cc:290] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.992072  1489 raft_consensus.cc:2804] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.992256  1482 ts_tablet_manager.cc:1434] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:24.992295  1459 heartbeater.cc:499] Master 127.0.213.190:36495 was elected leader, sending a full tablet report...
I20260812 06:17:24.992285  1489 raft_consensus.cc:697] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 1 LEADER]: Becoming Leader. State: Replica: b01b9a2a5700427cb97deecad035297a, State: Running, Role: LEADER
I20260812 06:17:24.992512  1489 consensus_queue.cc:237] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [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: "b01b9a2a5700427cb97deecad035297a" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 38115 } }
I20260812 06:17:24.993851  1244 catalog_manager.cc:5719] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a reported cstate change: term changed from 0 to 1, leader changed from <none> to b01b9a2a5700427cb97deecad035297a (127.0.213.129). New cstate: current_term: 1 leader_uuid: "b01b9a2a5700427cb97deecad035297a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b01b9a2a5700427cb97deecad035297a" member_type: VOTER last_known_addr { host: "127.0.213.129" port: 38115 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:25.052764   854 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.008s
I20260812 06:17:25.214609  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushMRSOp(395e4546297a47409fa74a012ff0a5d9): perf score=19.054940
I20260812 06:17:25.387939  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushMRSOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.173s	user 0.111s	sys 0.052s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":819,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45468,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:17:25.388620  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling LogGCOp(395e4546297a47409fa74a012ff0a5d9): free 20290830 bytes of WAL
I20260812 06:17:25.388859  1363 log_reader.cc:385] T 395e4546297a47409fa74a012ff0a5d9: removed 2 log segments from log reader
I20260812 06:17:25.388916  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000001 (ops 1-6)
I20260812 06:17:25.388960  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000002 (ops 7-10)
I20260812 06:17:25.392585  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: LogGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:25.392896  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:25.409650  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.410146  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9): 20513815 bytes on disk
I20260812 06:17:25.410555  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.411018  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:25.560439  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.149s	user 0.103s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":596,"lbm_read_time_us":11029,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24124,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":305,"threads_started":5,"update_count":2000}
I20260812 06:17:25.561017  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:25.604948  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.044s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19435,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.605533  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:25.617067  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.617705  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:25.783214  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.165s	user 0.112s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":491,"lbm_read_time_us":9881,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29336,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:17:25.783922  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:25.838213  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.054s	user 0.040s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22151,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.838768  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:25.978785  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.140s	user 0.092s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":175,"lbm_read_time_us":10409,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21826,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:25.979337  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:26.028172  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.049s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19102,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.028738  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:26.042122  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.042975  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:26.232496  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.189s	user 0.123s	sys 0.055s 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":1011,"lbm_read_time_us":12144,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29181,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:17:26.233060  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:26.279505  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.046s	user 0.033s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18258,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.280019  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:26.290936  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.291538  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:26.452524  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.161s	user 0.120s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1051,"lbm_read_time_us":10563,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31456,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:17:26.453094  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=11.118625
I20260812 06:17:26.496168  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.043s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15826,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:26.496740  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:26.508213  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.508693  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:26.517985  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3342,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.518447  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushMRSOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:26.550730  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushMRSOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":275,"dirs.run_wall_time_us":1457,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2012,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:26.551450  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling LogGCOp(395e4546297a47409fa74a012ff0a5d9): free 120553367 bytes of WAL
I20260812 06:17:26.551697  1363 log_reader.cc:385] T 395e4546297a47409fa74a012ff0a5d9: removed 12 log segments from log reader
I20260812 06:17:26.551759  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000003 (ops 11-15)
I20260812 06:17:26.551810  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000004 (ops 16-20)
I20260812 06:17:26.551847  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000005 (ops 21-24)
I20260812 06:17:26.551878  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000006 (ops 25-29)
I20260812 06:17:26.551904  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000007 (ops 30-34)
I20260812 06:17:26.551929  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000008 (ops 35-38)
I20260812 06:17:26.551954  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000009 (ops 39-43)
I20260812 06:17:26.551985  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000010 (ops 44-48)
I20260812 06:17:26.552014  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000011 (ops 49-53)
I20260812 06:17:26.552048  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000012 (ops 54-58)
I20260812 06:17:26.552075  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000013 (ops 59-63)
I20260812 06:17:26.552102  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000014 (ops 64-68)
I20260812 06:17:26.580283  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: LogGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:26.580737  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9): 447 bytes on disk
I20260812 06:17:26.581311  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.581857  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=3.181125
I20260812 06:17:26.605211  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.023s	user 0.009s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4137,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:26.605872  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:26.622699  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6898,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.623274  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:26.876658  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.253s	user 0.153s	sys 0.096s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020848,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1288,"lbm_read_time_us":17804,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40197,"lbm_writes_lt_1ms":743,"mutex_wait_us":604,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:17:26.877269  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=18.063937
I20260812 06:17:26.951236  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.074s	user 0.034s	sys 0.032s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29691,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.951685  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:26.962538  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.963068  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:27.175585  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.212s	user 0.133s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":671,"lbm_read_time_us":14705,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31708,"lbm_writes_lt_1ms":643,"mutex_wait_us":313,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":3000}
I20260812 06:17:27.176141  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=16.079562
I20260812 06:17:27.220718  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.044s	user 0.029s	sys 0.015s Metrics: {"bytes_written":17804726,"delete_count":0,"lbm_write_time_us":20206,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2170}
I20260812 06:17:27.221316  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.196750
I20260812 06:17:27.239287  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.018s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3670,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:27.239776  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:27.249173  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.009s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3402,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.249588  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:27.474391  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.225s	user 0.159s	sys 0.065s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918185,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":189,"lbm_read_time_us":15476,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36283,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":3000}
I20260812 06:17:27.480892  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:27.525170  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19787,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:27.525906  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:27.542466  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.543037  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:27.712122  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.169s	user 0.149s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":663,"lbm_read_time_us":10929,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27283,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:17:27.712766  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:27.768421  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.055s	user 0.044s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21583,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.768957  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:27.780282  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.780921  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:27.950578  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.169s	user 0.107s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":13332,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":28141,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:27.951167  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:28.007592  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.056s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20496,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.008183  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:28.018975  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.019773  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushMRSOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:28.052683  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushMRSOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1301,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1449,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:28.053404  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling LogGCOp(395e4546297a47409fa74a012ff0a5d9): free 121006439 bytes of WAL
I20260812 06:17:28.053671  1363 log_reader.cc:385] T 395e4546297a47409fa74a012ff0a5d9: removed 12 log segments from log reader
I20260812 06:17:28.053740  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000015 (ops 69-73)
I20260812 06:17:28.053784  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000016 (ops 74-78)
I20260812 06:17:28.053818  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000017 (ops 79-83)
I20260812 06:17:28.053840  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000018 (ops 84-88)
I20260812 06:17:28.053867  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000019 (ops 89-93)
I20260812 06:17:28.053898  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000020 (ops 94-98)
I20260812 06:17:28.053930  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000021 (ops 99-102)
I20260812 06:17:28.053958  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000022 (ops 103-107)
I20260812 06:17:28.053985  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000023 (ops 108-112)
I20260812 06:17:28.054013  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000024 (ops 113-117)
I20260812 06:17:28.054039  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000025 (ops 118-122)
I20260812 06:17:28.054070  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000026 (ops 123-127)
I20260812 06:17:28.081248  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: LogGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:28.081713  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9): 462 bytes on disk
I20260812 06:17:28.082257  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.082800  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=3.181125
I20260812 06:17:28.109194  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.026s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6362,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:28.109665  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:28.119407  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3479,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.119906  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:28.341075  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.221s	user 0.149s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":475,"lbm_read_time_us":16391,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33724,"lbm_writes_lt_1ms":743,"mutex_wait_us":26,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":42880,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:17:28.342446  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=18.063937
I20260812 06:17:28.401188  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.059s	user 0.037s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":24786,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:28.401655  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:28.423951  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.022s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.424489  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:28.440129  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.440789  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:28.626704  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.186s	user 0.128s	sys 0.057s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020630,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1153,"lbm_read_time_us":15079,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37349,"lbm_writes_lt_1ms":743,"mutex_wait_us":493,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3500}
I20260812 06:17:28.627313  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=15.087375
I20260812 06:17:28.665850  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":16600,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:28.666456  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:28.681270  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.015s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5535,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.681723  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:28.833560  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.152s	user 0.106s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815671,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":8691,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28251,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":44800,"update_count":2500}
I20260812 06:17:28.836843  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:28.885113  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.048s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21120,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.885623  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:28.896593  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.897168  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:29.063622  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.166s	user 0.112s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1127,"lbm_read_time_us":11520,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25068,"lbm_writes_lt_1ms":543,"mutex_wait_us":461,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.064183  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:29.107754  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19175,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.108322  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:29.253530  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.145s	user 0.108s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":632,"lbm_read_time_us":9590,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24770,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:29.254072  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=14.095187
I20260812 06:17:29.305135  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23036,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.305630  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:29.316655  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.317147  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushMRSOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:29.350978  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushMRSOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.034s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1283,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1444,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:29.351769  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling LogGCOp(395e4546297a47409fa74a012ff0a5d9): free 115943419 bytes of WAL
I20260812 06:17:29.351984  1363 log_reader.cc:385] T 395e4546297a47409fa74a012ff0a5d9: removed 11 log segments from log reader
I20260812 06:17:29.352022  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000027 (ops 128-132)
I20260812 06:17:29.352061  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000028 (ops 133-137)
I20260812 06:17:29.352093  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000029 (ops 138-142)
I20260812 06:17:29.352160  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000030 (ops 143-147)
I20260812 06:17:29.352197  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000031 (ops 148-152)
I20260812 06:17:29.352246  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000032 (ops 153-157)
I20260812 06:17:29.352279  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000033 (ops 158-162)
I20260812 06:17:29.352334  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000034 (ops 163-167)
I20260812 06:17:29.352409  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000035 (ops 168-172)
I20260812 06:17:29.352432  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000036 (ops 173-177)
I20260812 06:17:29.352450  1363 log.cc:1079] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: Deleting log segment in path: /tmp/dist-test-taskH_Zaph/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515439544724-854-0/minicluster-data/ts-0-root/wals/395e4546297a47409fa74a012ff0a5d9/wal-000000037 (ops 178-182)
I20260812 06:17:29.373664  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: LogGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.022s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:17:29.374053  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9): 447 bytes on disk
I20260812 06:17:29.374472  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: UndoDeltaBlockGCOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.375149  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:29.395243  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.020s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.395735  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:29.411034  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.411685  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:29.639894  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.228s	user 0.132s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":326,"lbm_read_time_us":14800,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37132,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":96,"threads_started":1,"update_count":3500}
I20260812 06:17:29.641242  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=18.063937
I20260812 06:17:29.711126  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.069s	user 0.025s	sys 0.037s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":30969,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":500,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.711679  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9): perf score=2.188937
I20260812 06:17:29.727489  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: FlushDeltaMemStoresOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.728451  1461 maintenance_manager.cc:419] P b01b9a2a5700427cb97deecad035297a: Scheduling MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9): perf score=1.000000
I20260812 06:17:29.811090   854 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.758s	user 1.694s	sys 0.183s
I20260812 06:17:29.880122   854 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.069s	user 0.001s	sys 0.000s
I20260812 06:17:29.880693   854 tablet_server.cc:179] TabletServer@127.0.213.129:0 shutting down...
I20260812 06:17:29.901875  1363 maintenance_manager.cc:643] P b01b9a2a5700427cb97deecad035297a: MajorDeltaCompactionOp(395e4546297a47409fa74a012ff0a5d9) complete. Timing: real 0.173s	user 0.124s	sys 0.049s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":13795,"lbm_reads_lt_1ms":668,"lbm_write_time_us":26625,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24704,"update_count":3000}
I20260812 06:17:29.902608   854 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:29.902909   854 tablet_replica.cc:333] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a: stopping tablet replica
I20260812 06:17:29.903041   854 raft_consensus.cc:2243] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.903208   854 raft_consensus.cc:2272] T 395e4546297a47409fa74a012ff0a5d9 P b01b9a2a5700427cb97deecad035297a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.919567   854 tablet_server.cc:196] TabletServer@127.0.213.129:0 shutdown complete.
I20260812 06:17:29.953615   854 master.cc:562] Master@127.0.213.190:36495 shutting down...
I20260812 06:17:29.957036   854 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.957211   854 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.957260   854 tablet_replica.cc:333] T 00000000000000000000000000000000 P 966d841d9ec242a0bfd38653b93d6092: stopping tablet replica
I20260812 06:17:29.969399   854 master.cc:584] Master@127.0.213.190:36495 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5190 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10494 ms total)

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