[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:51.663612  2740 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.173.62:36395
I20260812 06:18:51.664611  2740 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:51.665198  2740 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:51.671432  2746 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:51.671482  2740 server_base.cc:1061] running on GCE node
W20260812 06:18:51.671425  2748 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:51.671770  2745 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:51.672235  2740 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:51.672398  2740 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:51.672463  2740 hybrid_clock.cc:648] HybridClock initialized: now 1786515531672460 us; error 0 us; skew 500 ppm
I20260812 06:18:51.674178  2740 webserver.cc:533] Webserver started at http://127.2.173.62:46741/ using document root <none> and password file <none>
I20260812 06:18:51.674778  2740 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:51.674868  2740 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:51.675102  2740 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:51.676740  2740 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/master-0-root/instance:
uuid: "5f6fcd774c234ec6b7d78f83318e4bfc"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-gp6n"
I20260812 06:18:51.680091  2740 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:51.682065  2754 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:51.683024  2740 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:51.683156  2740 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/master-0-root
uuid: "5f6fcd774c234ec6b7d78f83318e4bfc"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-gp6n"
I20260812 06:18:51.683259  2740 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:51.698814  2740 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:51.699406  2740 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:51.699580  2740 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:51.707206  2740 rpc_server.cc:307] RPC server started. Bound to: 127.2.173.62:36395
I20260812 06:18:51.707216  2819 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.173.62:36395 every 8 connection(s)
I20260812 06:18:51.709367  2820 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:51.714529  2820 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc: Bootstrap starting.
I20260812 06:18:51.716727  2820 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:51.717514  2820 log.cc:826] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:51.719077  2820 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc: No bootstrap required, opened a new log
I20260812 06:18:51.721889  2820 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f6fcd774c234ec6b7d78f83318e4bfc" member_type: VOTER }
I20260812 06:18:51.722043  2820 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:51.722090  2820 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5f6fcd774c234ec6b7d78f83318e4bfc, State: Initialized, Role: FOLLOWER
I20260812 06:18:51.722644  2820 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [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: "5f6fcd774c234ec6b7d78f83318e4bfc" member_type: VOTER }
I20260812 06:18:51.722779  2820 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:51.722826  2820 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:51.722906  2820 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:51.723606  2820 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f6fcd774c234ec6b7d78f83318e4bfc" member_type: VOTER }
I20260812 06:18:51.723966  2820 leader_election.cc:304] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [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: 5f6fcd774c234ec6b7d78f83318e4bfc; no voters: 
I20260812 06:18:51.724207  2820 leader_election.cc:290] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:51.724359  2823 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:51.724608  2823 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 1 LEADER]: Becoming Leader. State: Replica: 5f6fcd774c234ec6b7d78f83318e4bfc, State: Running, Role: LEADER
I20260812 06:18:51.725029  2823 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [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: "5f6fcd774c234ec6b7d78f83318e4bfc" member_type: VOTER }
I20260812 06:18:51.725226  2820 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:51.726945  2824 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5f6fcd774c234ec6b7d78f83318e4bfc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f6fcd774c234ec6b7d78f83318e4bfc" member_type: VOTER } }
I20260812 06:18:51.726933  2825 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5f6fcd774c234ec6b7d78f83318e4bfc. Latest consensus state: current_term: 1 leader_uuid: "5f6fcd774c234ec6b7d78f83318e4bfc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f6fcd774c234ec6b7d78f83318e4bfc" member_type: VOTER } }
I20260812 06:18:51.727078  2825 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:51.727078  2824 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:51.727506  2740 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:51.729305  2843 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:51.729367  2843 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:51.729444  2842 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:51.730157  2842 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:51.734599  2842 catalog_manager.cc:1383] Generated new cluster ID: 246152d7076d4073af0411ce4f909b79
I20260812 06:18:51.734660  2842 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:51.751988  2842 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:51.753135  2842 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:51.763015  2842 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc: Generated new TSK 0
I20260812 06:18:51.763729  2842 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:51.792292  2740 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:51.795063  2847 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:51.795111  2848 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:51.795303  2851 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:51.795303  2740 server_base.cc:1061] running on GCE node
I20260812 06:18:51.795534  2740 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:51.795583  2740 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:51.795605  2740 hybrid_clock.cc:648] HybridClock initialized: now 1786515531795606 us; error 0 us; skew 500 ppm
I20260812 06:18:51.796536  2740 webserver.cc:533] Webserver started at http://127.2.173.1:34963/ using document root <none> and password file <none>
I20260812 06:18:51.796700  2740 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:51.796758  2740 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:51.796834  2740 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:51.797264  2740 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/instance:
uuid: "a8fe7666cc014bb78e9f7a370e669474"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-gp6n"
I20260812 06:18:51.799090  2740 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:51.800163  2856 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:51.800469  2740 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:51.800555  2740 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root
uuid: "a8fe7666cc014bb78e9f7a370e669474"
format_stamp: "Formatted at 2026-08-12 06:18:51 on dist-test-slave-gp6n"
I20260812 06:18:51.800632  2740 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:51.814133  2740 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:51.814658  2740 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:51.815166  2740 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:51.816052  2740 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:51.816104  2740 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:51.816174  2740 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:51.816211  2740 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:51.823338  2740 rpc_server.cc:307] RPC server started. Bound to: 127.2.173.1:36955
I20260812 06:18:51.823381  2936 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.173.1:36955 every 8 connection(s)
I20260812 06:18:51.839073  2938 heartbeater.cc:344] Connected to a master server at 127.2.173.62:36395
I20260812 06:18:51.839341  2938 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:51.839818  2938 heartbeater.cc:507] Master 127.2.173.62:36395 requested a full tablet report, sending...
I20260812 06:18:51.841234  2774 ts_manager.cc:194] Registered new tserver with Master: a8fe7666cc014bb78e9f7a370e669474 (127.2.173.1:36955)
I20260812 06:18:51.841683  2740 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017695659s
I20260812 06:18:51.842711  2774 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47790
I20260812 06:18:51.850807  2774 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47798:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:51.864997  2895 tablet_service.cc:1511] Processing CreateTablet for tablet f40eb436fa4e48c08da54c6008271ef2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a1ba9e593ecc4b29b48bc4235e38caa6]), partition=
I20260812 06:18:51.865470  2895 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f40eb436fa4e48c08da54c6008271ef2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:51.867751  2954 tablet_bootstrap.cc:492] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Bootstrap starting.
I20260812 06:18:51.869058  2954 tablet_bootstrap.cc:654] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:51.870692  2954 tablet_bootstrap.cc:492] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: No bootstrap required, opened a new log
I20260812 06:18:51.870776  2954 ts_tablet_manager.cc:1403] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:51.871276  2954 raft_consensus.cc:359] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8fe7666cc014bb78e9f7a370e669474" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 36955 } }
I20260812 06:18:51.871376  2954 raft_consensus.cc:385] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:51.871398  2954 raft_consensus.cc:740] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a8fe7666cc014bb78e9f7a370e669474, State: Initialized, Role: FOLLOWER
I20260812 06:18:51.871546  2954 consensus_queue.cc:260] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [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: "a8fe7666cc014bb78e9f7a370e669474" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 36955 } }
I20260812 06:18:51.871619  2954 raft_consensus.cc:399] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:51.871688  2954 raft_consensus.cc:493] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:51.871764  2954 raft_consensus.cc:3060] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:51.872776  2954 raft_consensus.cc:515] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8fe7666cc014bb78e9f7a370e669474" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 36955 } }
I20260812 06:18:51.872915  2954 leader_election.cc:304] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [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: a8fe7666cc014bb78e9f7a370e669474; no voters: 
I20260812 06:18:51.873168  2954 leader_election.cc:290] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:51.873260  2956 raft_consensus.cc:2804] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:51.873445  2956 raft_consensus.cc:697] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 1 LEADER]: Becoming Leader. State: Replica: a8fe7666cc014bb78e9f7a370e669474, State: Running, Role: LEADER
I20260812 06:18:51.873577  2954 ts_tablet_manager.cc:1434] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:51.873646  2956 consensus_queue.cc:237] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [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: "a8fe7666cc014bb78e9f7a370e669474" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 36955 } }
I20260812 06:18:51.873874  2938 heartbeater.cc:499] Master 127.2.173.62:36395 was elected leader, sending a full tablet report...
I20260812 06:18:51.876421  2774 catalog_manager.cc:5719] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 reported cstate change: term changed from 0 to 1, leader changed from <none> to a8fe7666cc014bb78e9f7a370e669474 (127.2.173.1). New cstate: current_term: 1 leader_uuid: "a8fe7666cc014bb78e9f7a370e669474" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8fe7666cc014bb78e9f7a370e669474" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 36955 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:51.947229  2740 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.025s	sys 0.007s
I20260812 06:18:52.074594  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2): perf score=15.086190
I20260812 06:18:52.219980  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.145s	user 0.129s	sys 0.012s Metrics: {"bytes_written":8615322,"cfile_init":1,"compiler_manager_pool.queue_time_us":457,"delete_count":0,"dirs.queue_time_us":2830,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":929,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33189,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":97,"threads_started":1,"update_count":1050}
I20260812 06:18:52.221194  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling LogGCOp(f40eb436fa4e48c08da54c6008271ef2): free 20743880 bytes of WAL
I20260812 06:18:52.221571  2863 log_reader.cc:385] T f40eb436fa4e48c08da54c6008271ef2: removed 2 log segments from log reader
I20260812 06:18:52.221683  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000001 (ops 1-6)
I20260812 06:18:52.221786  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000002 (ops 7-11)
I20260812 06:18:52.227162  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: LogGCOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:52.227496  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:52.240732  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4965,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.241165  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling UndoDeltaBlockGCOp(f40eb436fa4e48c08da54c6008271ef2): 16411395 bytes on disk
I20260812 06:18:52.241755  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: UndoDeltaBlockGCOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:18:52.242165  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:52.353849  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.112s	user 0.087s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569855,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":809,"lbm_read_time_us":7381,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20918,"lbm_writes_lt_1ms":343,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":316,"threads_started":5,"update_count":1500}
I20260812 06:18:52.354467  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:52.400118  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.045s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18416,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.400601  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:52.410609  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.411244  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:52.539721  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.128s	user 0.102s	sys 0.026s 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":152,"lbm_read_time_us":8809,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25204,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:52.540309  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:52.591836  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.051s	user 0.019s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15503,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.592339  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:52.602722  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.603147  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:52.754489  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.151s	user 0.119s	sys 0.032s 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":288,"lbm_read_time_us":11290,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25028,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:52.755065  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:52.800662  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.045s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18506,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.801110  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:52.811685  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.812410  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:52.956018  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.143s	user 0.118s	sys 0.025s 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":1428,"lbm_read_time_us":8824,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27467,"lbm_writes_lt_1ms":443,"mutex_wait_us":293,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:52.956650  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:53.003767  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.047s	user 0.030s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23425,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.004274  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:53.014395  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.015282  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:53.140801  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.125s	user 0.089s	sys 0.034s 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":205,"lbm_read_time_us":9070,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23369,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:53.141317  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:53.193121  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.052s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17131,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.193638  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:53.204264  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4113,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.204705  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:53.348716  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.144s	user 0.107s	sys 0.037s 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":1001,"lbm_read_time_us":12155,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21722,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.349323  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:53.392161  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.043s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14671,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.392746  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:53.403868  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.404517  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:53.524121  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.119s	user 0.089s	sys 0.030s 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":1014,"lbm_read_time_us":7671,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24313,"lbm_writes_lt_1ms":443,"mutex_wait_us":262,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:18:53.524716  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:53.561903  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.037s	user 0.008s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14464,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.562418  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:53.577286  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.577836  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:53.607121  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1435,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1624,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:53.607872  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling LogGCOp(f40eb436fa4e48c08da54c6008271ef2): free 124257238 bytes of WAL
I20260812 06:18:53.608108  2863 log_reader.cc:385] T f40eb436fa4e48c08da54c6008271ef2: removed 12 log segments from log reader
I20260812 06:18:53.608152  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000003 (ops 12-16)
I20260812 06:18:53.608201  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000004 (ops 17-20)
I20260812 06:18:53.608246  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000005 (ops 21-25)
I20260812 06:18:53.608289  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000006 (ops 26-30)
I20260812 06:18:53.608331  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000007 (ops 31-35)
I20260812 06:18:53.608397  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000008 (ops 36-40)
I20260812 06:18:53.608444  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000009 (ops 41-45)
I20260812 06:18:53.608489  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000010 (ops 46-50)
I20260812 06:18:53.608530  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000011 (ops 51-55)
I20260812 06:18:53.608570  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000012 (ops 56-60)
I20260812 06:18:53.608611  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000013 (ops 61-65)
I20260812 06:18:53.608650  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000014 (ops 66-70)
I20260812 06:18:53.636128  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: LogGCOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.028s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:18:53.636734  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=3.181125
I20260812 06:18:53.648218  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:53.648643  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling UndoDeltaBlockGCOp(f40eb436fa4e48c08da54c6008271ef2): 483 bytes on disk
I20260812 06:18:53.649029  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: UndoDeltaBlockGCOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.649475  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:53.659051  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3812,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:53.659651  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:53.824788  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.165s	user 0.119s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":609,"lbm_read_time_us":10576,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32561,"lbm_writes_lt_1ms":643,"mutex_wait_us":299,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14592,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:53.825477  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=14.095187
I20260812 06:18:53.879686  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.054s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22283,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.880134  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:53.892772  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4472,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.893417  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:54.059690  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.166s	user 0.109s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":11757,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29795,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:18:54.060366  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=14.095187
I20260812 06:18:54.118155  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.058s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24614,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.118646  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:54.267470  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.149s	user 0.088s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":305,"lbm_read_time_us":10267,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26061,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.268234  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=11.118625
I20260812 06:18:54.307611  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.039s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16562,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:54.308246  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:54.325788  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6317,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.326500  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:54.460202  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.133s	user 0.102s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":602,"lbm_read_time_us":8189,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26135,"lbm_writes_lt_1ms":443,"mutex_wait_us":305,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:18:54.460924  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:54.500824  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.040s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17517,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":1500}
I20260812 06:18:54.501284  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:54.514286  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.514849  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:54.634073  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.119s	user 0.102s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":89,"lbm_read_time_us":8335,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23900,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.634809  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:54.671417  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15873,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.671967  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:54.686606  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.687095  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:54.808995  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.122s	user 0.079s	sys 0.039s 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":610,"lbm_read_time_us":9531,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21938,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.810089  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:54.852339  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.042s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13151,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.852924  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:54.867981  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.868466  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:55.008097  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.139s	user 0.087s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":143,"lbm_read_time_us":10446,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21921,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:18:55.008837  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=10.126437
I20260812 06:18:55.053561  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.045s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18434,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.054021  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:55.064235  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.065009  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:55.096397  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.031s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":1616,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2073,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:55.097152  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling LogGCOp(f40eb436fa4e48c08da54c6008271ef2): free 133477394 bytes of WAL
I20260812 06:18:55.097380  2863 log_reader.cc:385] T f40eb436fa4e48c08da54c6008271ef2: removed 13 log segments from log reader
I20260812 06:18:55.097424  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000015 (ops 71-75)
I20260812 06:18:55.097452  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000016 (ops 76-80)
I20260812 06:18:55.097524  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000017 (ops 81-85)
I20260812 06:18:55.097570  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000018 (ops 86-90)
I20260812 06:18:55.097608  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000019 (ops 91-95)
I20260812 06:18:55.097656  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000020 (ops 96-100)
I20260812 06:18:55.097697  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000021 (ops 101-105)
I20260812 06:18:55.097738  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000022 (ops 106-110)
I20260812 06:18:55.097781  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000023 (ops 111-115)
I20260812 06:18:55.097823  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000024 (ops 116-120)
I20260812 06:18:55.097862  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000025 (ops 121-125)
I20260812 06:18:55.097903  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000026 (ops 126-130)
I20260812 06:18:55.097941  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000027 (ops 131-135)
I20260812 06:18:55.126924  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: LogGCOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:55.127303  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling UndoDeltaBlockGCOp(f40eb436fa4e48c08da54c6008271ef2): 482 bytes on disk
I20260812 06:18:55.127791  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: UndoDeltaBlockGCOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:18:55.128317  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=4.173312
I20260812 06:18:55.150681  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.022s	user 0.009s	sys 0.013s Metrics: {"bytes_written":6235919,"delete_count":0,"lbm_write_time_us":6403,"lbm_writes_lt_1ms":155,"reinsert_count":0,"update_count":760}
I20260812 06:18:55.151177  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:55.157166  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.006s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1969352,"delete_count":0,"lbm_write_time_us":1881,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:18:55.157567  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:55.358306  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.201s	user 0.160s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877286,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":516,"lbm_read_time_us":14767,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33487,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:18:55.360146  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=14.095187
I20260812 06:18:55.421615  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.061s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18278,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.422209  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:55.433094  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.433548  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:55.612453  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.179s	user 0.111s	sys 0.058s 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":1200,"lbm_read_time_us":11940,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28907,"lbm_writes_lt_1ms":543,"mutex_wait_us":396,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:55.613042  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=14.095187
I20260812 06:18:55.663960  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.051s	user 0.020s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17012,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.664539  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:55.682804  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.018s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.683307  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:55.842471  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.159s	user 0.108s	sys 0.049s 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":445,"lbm_read_time_us":12035,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27424,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:55.843130  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=11.118625
I20260812 06:18:55.877183  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14569,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:55.877720  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:55.899960  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.022s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5141,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:55.900393  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:55.910611  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.911058  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:56.091161  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.180s	user 0.123s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":119,"lbm_read_time_us":11545,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29221,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:18:56.091828  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=14.095187
I20260812 06:18:56.146203  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.054s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23442,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.146742  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:56.158126  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.158649  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:56.314023  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.155s	user 0.123s	sys 0.021s 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":152,"lbm_read_time_us":10913,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30070,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":2500}
I20260812 06:18:56.314663  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=14.095187
I20260812 06:18:56.359882  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.045s	user 0.012s	sys 0.029s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:56.360394  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:56.375844  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.015s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5681,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.376526  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:56.513201  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.136s	user 0.102s	sys 0.033s 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":745,"lbm_read_time_us":9591,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26808,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:18:56.513787  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=11.118625
I20260812 06:18:56.550458  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15653,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:56.551159  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:56.575577  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.024s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4931,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.576118  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:56.586087  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.586678  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:56.621187  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushMRSOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1620,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1864,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:56.622069  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling LogGCOp(f40eb436fa4e48c08da54c6008271ef2): free 124710570 bytes of WAL
I20260812 06:18:56.622309  2863 log_reader.cc:385] T f40eb436fa4e48c08da54c6008271ef2: removed 12 log segments from log reader
I20260812 06:18:56.622376  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000028 (ops 136-140)
I20260812 06:18:56.622444  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000029 (ops 141-145)
I20260812 06:18:56.622485  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000030 (ops 146-150)
I20260812 06:18:56.622527  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000031 (ops 151-155)
I20260812 06:18:56.622566  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000032 (ops 156-160)
I20260812 06:18:56.622601  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000033 (ops 161-165)
I20260812 06:18:56.622637  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000034 (ops 166-170)
I20260812 06:18:56.622676  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000035 (ops 171-175)
I20260812 06:18:56.622714  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000036 (ops 176-180)
I20260812 06:18:56.622752  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000037 (ops 181-185)
I20260812 06:18:56.622790  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000038 (ops 186-190)
I20260812 06:18:56.622828  2863 log.cc:1079] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/f40eb436fa4e48c08da54c6008271ef2/wal-000000039 (ops 191-195)
I20260812 06:18:56.648979  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: LogGCOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:56.649415  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=3.181125
I20260812 06:18:56.666695  2740 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.719s	user 1.816s	sys 0.109s
I20260812 06:18:56.668272  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.019s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7054,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:56.668733  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2): perf score=2.188937
I20260812 06:18:56.682906  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: FlushDeltaMemStoresOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5609,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":450}
I20260812 06:18:56.683470  2940 maintenance_manager.cc:419] P a8fe7666cc014bb78e9f7a370e669474: Scheduling MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2): perf score=1.000000
I20260812 06:18:56.741232  2740 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.074s	user 0.001s	sys 0.000s
I20260812 06:18:56.741868  2740 tablet_server.cc:179] TabletServer@127.2.173.1:0 shutting down...
I20260812 06:18:56.829298  2863 maintenance_manager.cc:643] P a8fe7666cc014bb78e9f7a370e669474: MajorDeltaCompactionOp(f40eb436fa4e48c08da54c6008271ef2) complete. Timing: real 0.146s	user 0.121s	sys 0.024s Metrics: {"cfile_cache_hit":291,"cfile_cache_hit_bytes":11778631,"cfile_cache_miss":444,"cfile_cache_miss_bytes":21201220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1039,"lbm_read_time_us":7832,"lbm_reads_lt_1ms":476,"lbm_write_time_us":32085,"lbm_writes_lt_1ms":743,"mutex_wait_us":326,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:18:56.830037  2740 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:56.830754  2740 tablet_replica.cc:333] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474: stopping tablet replica
I20260812 06:18:56.831005  2740 raft_consensus.cc:2243] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:56.831245  2740 raft_consensus.cc:2272] T f40eb436fa4e48c08da54c6008271ef2 P a8fe7666cc014bb78e9f7a370e669474 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:56.836552  2740 tablet_server.cc:196] TabletServer@127.2.173.1:0 shutdown complete.
I20260812 06:18:56.887375  2740 master.cc:562] Master@127.2.173.62:36395 shutting down...
I20260812 06:18:56.891366  2740 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:56.891558  2740 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:56.891654  2740 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5f6fcd774c234ec6b7d78f83318e4bfc: stopping tablet replica
I20260812 06:18:56.904084  2740 master.cc:584] Master@127.2.173.62:36395 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5327 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:56.991267  2740 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.173.62:38075
I20260812 06:18:56.991674  2740 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:56.993652  2979 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:56.993759  2740 server_base.cc:1061] running on GCE node
W20260812 06:18:56.993713  2981 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:56.993796  2978 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:56.994028  2740 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:56.994092  2740 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:56.994117  2740 hybrid_clock.cc:648] HybridClock initialized: now 1786515536994116 us; error 0 us; skew 500 ppm
I20260812 06:18:56.995002  2740 webserver.cc:533] Webserver started at http://127.2.173.62:37331/ using document root <none> and password file <none>
I20260812 06:18:56.995173  2740 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:56.995236  2740 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:56.995321  2740 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:56.995698  2740 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/master-0-root/instance:
uuid: "c3cc966a8c5f4861a3ece1f6008b40b2"
format_stamp: "Formatted at 2026-08-12 06:18:56 on dist-test-slave-gp6n"
I20260812 06:18:56.997129  2740 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:56.997980  2986 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:56.998235  2740 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:56.998323  2740 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/master-0-root
uuid: "c3cc966a8c5f4861a3ece1f6008b40b2"
format_stamp: "Formatted at 2026-08-12 06:18:56 on dist-test-slave-gp6n"
I20260812 06:18:56.998407  2740 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:57.008772  2740 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.009127  2740 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.013341  2740 rpc_server.cc:307] RPC server started. Bound to: 127.2.173.62:38075
I20260812 06:18:57.015906  3047 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.173.62:38075 every 8 connection(s)
I20260812 06:18:57.018507  3048 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:57.030573  3048 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2: Bootstrap starting.
I20260812 06:18:57.031467  3048 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.032589  3048 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2: No bootstrap required, opened a new log
I20260812 06:18:57.033057  3048 raft_consensus.cc:359] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cc966a8c5f4861a3ece1f6008b40b2" member_type: VOTER }
I20260812 06:18:57.033150  3048 raft_consensus.cc:385] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.033172  3048 raft_consensus.cc:740] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c3cc966a8c5f4861a3ece1f6008b40b2, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.033319  3048 consensus_queue.cc:260] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [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: "c3cc966a8c5f4861a3ece1f6008b40b2" member_type: VOTER }
I20260812 06:18:57.033406  3048 raft_consensus.cc:399] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.033437  3048 raft_consensus.cc:493] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.033474  3048 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.034157  3048 raft_consensus.cc:515] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cc966a8c5f4861a3ece1f6008b40b2" member_type: VOTER }
I20260812 06:18:57.034267  3048 leader_election.cc:304] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [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: c3cc966a8c5f4861a3ece1f6008b40b2; no voters: 
I20260812 06:18:57.034451  3048 leader_election.cc:290] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.034603  3051 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.034840  3051 raft_consensus.cc:697] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 1 LEADER]: Becoming Leader. State: Replica: c3cc966a8c5f4861a3ece1f6008b40b2, State: Running, Role: LEADER
I20260812 06:18:57.034868  3048 sys_catalog.cc:565] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:57.034976  3051 consensus_queue.cc:237] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [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: "c3cc966a8c5f4861a3ece1f6008b40b2" member_type: VOTER }
I20260812 06:18:57.035463  3052 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c3cc966a8c5f4861a3ece1f6008b40b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cc966a8c5f4861a3ece1f6008b40b2" member_type: VOTER } }
I20260812 06:18:57.035488  3053 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c3cc966a8c5f4861a3ece1f6008b40b2. Latest consensus state: current_term: 1 leader_uuid: "c3cc966a8c5f4861a3ece1f6008b40b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cc966a8c5f4861a3ece1f6008b40b2" member_type: VOTER } }
I20260812 06:18:57.035645  3053 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.035833  3052 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.036178  3058 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:57.037079  3058 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:57.037317  2740 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:57.038968  3058 catalog_manager.cc:1383] Generated new cluster ID: 0a76224a5aa14bd980ed7b4a0335a8d3
I20260812 06:18:57.039031  3058 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:57.061311  3058 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:57.061981  3058 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:57.073359  3058 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2: Generated new TSK 0
I20260812 06:18:57.073578  3058 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:57.101977  2740 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.104017  3071 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:57.104128  3072 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:57.104130  3074 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:57.104419  2740 server_base.cc:1061] running on GCE node
I20260812 06:18:57.104604  2740 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.104645  2740 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:57.104661  2740 hybrid_clock.cc:648] HybridClock initialized: now 1786515537104661 us; error 0 us; skew 500 ppm
I20260812 06:18:57.105522  2740 webserver.cc:533] Webserver started at http://127.2.173.1:41533/ using document root <none> and password file <none>
I20260812 06:18:57.105659  2740 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.105702  2740 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.105755  2740 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.106101  2740 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/instance:
uuid: "4ba970ba991543f69ce1ee1854925716"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-gp6n"
I20260812 06:18:57.107625  2740 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:57.108500  3082 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.108767  2740 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:57.108829  2740 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root
uuid: "4ba970ba991543f69ce1ee1854925716"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-gp6n"
I20260812 06:18:57.108882  2740 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:57.123907  2740 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.124300  2740 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.124583  2740 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:57.125093  2740 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:57.125133  2740 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.125195  2740 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:57.125234  2740 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.129678  2740 rpc_server.cc:307] RPC server started. Bound to: 127.2.173.1:38107
I20260812 06:18:57.130494  3156 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.173.1:38107 every 8 connection(s)
I20260812 06:18:57.140101  3157 heartbeater.cc:344] Connected to a master server at 127.2.173.62:38075
I20260812 06:18:57.140223  3157 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:57.140429  3157 heartbeater.cc:507] Master 127.2.173.62:38075 requested a full tablet report, sending...
I20260812 06:18:57.141108  3006 ts_manager.cc:194] Registered new tserver with Master: 4ba970ba991543f69ce1ee1854925716 (127.2.173.1:38107)
I20260812 06:18:57.141682  2740 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011112348s
I20260812 06:18:57.141899  3006 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51770
I20260812 06:18:57.148492  3006 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51782:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:57.157054  3116 tablet_service.cc:1511] Processing CreateTablet for tablet 59cbef5f259b47e685b5b2a3429e7b42 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bb54ce8f314e48a3a05406816a60b600]), partition=
I20260812 06:18:57.157341  3116 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 59cbef5f259b47e685b5b2a3429e7b42. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:57.159195  3170 tablet_bootstrap.cc:492] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Bootstrap starting.
I20260812 06:18:57.160048  3170 tablet_bootstrap.cc:654] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.161080  3170 tablet_bootstrap.cc:492] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: No bootstrap required, opened a new log
I20260812 06:18:57.161150  3170 ts_tablet_manager.cc:1403] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:57.161510  3170 raft_consensus.cc:359] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ba970ba991543f69ce1ee1854925716" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 38107 } }
I20260812 06:18:57.161592  3170 raft_consensus.cc:385] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.161613  3170 raft_consensus.cc:740] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4ba970ba991543f69ce1ee1854925716, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.161741  3170 consensus_queue.cc:260] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [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: "4ba970ba991543f69ce1ee1854925716" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 38107 } }
I20260812 06:18:57.161855  3170 raft_consensus.cc:399] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.161900  3170 raft_consensus.cc:493] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.161958  3170 raft_consensus.cc:3060] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.162870  3170 raft_consensus.cc:515] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ba970ba991543f69ce1ee1854925716" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 38107 } }
I20260812 06:18:57.162987  3170 leader_election.cc:304] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [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: 4ba970ba991543f69ce1ee1854925716; no voters: 
I20260812 06:18:57.163146  3170 leader_election.cc:290] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.163265  3172 raft_consensus.cc:2804] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.163488  3172 raft_consensus.cc:697] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 1 LEADER]: Becoming Leader. State: Replica: 4ba970ba991543f69ce1ee1854925716, State: Running, Role: LEADER
I20260812 06:18:57.163523  3170 ts_tablet_manager.cc:1434] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:57.163537  3157 heartbeater.cc:499] Master 127.2.173.62:38075 was elected leader, sending a full tablet report...
I20260812 06:18:57.163663  3172 consensus_queue.cc:237] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [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: "4ba970ba991543f69ce1ee1854925716" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 38107 } }
I20260812 06:18:57.165032  3006 catalog_manager.cc:5719] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4ba970ba991543f69ce1ee1854925716 (127.2.173.1). New cstate: current_term: 1 leader_uuid: "4ba970ba991543f69ce1ee1854925716" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ba970ba991543f69ce1ee1854925716" member_type: VOTER last_known_addr { host: "127.2.173.1" port: 38107 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:57.224031  2740 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.015s	sys 0.008s
I20260812 06:18:57.381155  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=22.031503
I20260812 06:18:57.542904  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.162s	user 0.108s	sys 0.052s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":959,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40629,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:57.543660  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling LogGCOp(59cbef5f259b47e685b5b2a3429e7b42): free 20290830 bytes of WAL
I20260812 06:18:57.543903  3087 log_reader.cc:385] T 59cbef5f259b47e685b5b2a3429e7b42: removed 2 log segments from log reader
I20260812 06:18:57.543964  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000001 (ops 1-6)
I20260812 06:18:57.544014  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000002 (ops 7-10)
I20260812 06:18:57.549316  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: LogGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:57.549692  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:57.567867  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.018s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.568331  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:57.706943  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.138s	user 0.103s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":610,"lbm_read_time_us":10064,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25169,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":440,"threads_started":5,"update_count":2000}
I20260812 06:18:57.707625  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=10.126437
I20260812 06:18:57.740993  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.033s	user 0.006s	sys 0.025s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14709,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.741568  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42): 20513816 bytes on disk
I20260812 06:18:57.742033  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.742566  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:57.757279  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.757750  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:57.881956  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.124s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":9747,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23640,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2000}
I20260812 06:18:57.882663  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=10.126437
I20260812 06:18:57.926524  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.044s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14093,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.927033  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:57.938642  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.011s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.939056  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:58.086819  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.148s	user 0.128s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":11563,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24123,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:18:58.087657  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=10.126437
I20260812 06:18:58.130142  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.042s	user 0.011s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20437,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.130735  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:58.144767  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.145257  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:58.280895  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.135s	user 0.102s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":8780,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26624,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:18:58.281620  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=10.126437
I20260812 06:18:58.326484  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.045s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17307,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.326972  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:58.338747  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4569,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.339458  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:58.459270  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.120s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1308,"lbm_read_time_us":8248,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23399,"lbm_writes_lt_1ms":443,"mutex_wait_us":373,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:58.459781  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=10.126437
I20260812 06:18:58.510386  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.050s	user 0.020s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18702,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.510917  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:58.521193  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.521641  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:58.660148  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.138s	user 0.090s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":10245,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21093,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:18:58.660660  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=10.126437
I20260812 06:18:58.698089  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15835,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.698603  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:58.709753  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.710359  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:58.739931  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1408,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1624,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:58.740588  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling LogGCOp(59cbef5f259b47e685b5b2a3429e7b42): free 112692305 bytes of WAL
I20260812 06:18:58.740815  3087 log_reader.cc:385] T 59cbef5f259b47e685b5b2a3429e7b42: removed 11 log segments from log reader
I20260812 06:18:58.740860  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000003 (ops 11-15)
I20260812 06:18:58.740890  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000004 (ops 16-20)
I20260812 06:18:58.740942  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000005 (ops 21-25)
I20260812 06:18:58.740988  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000006 (ops 26-30)
I20260812 06:18:58.741006  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000007 (ops 31-35)
I20260812 06:18:58.741060  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000008 (ops 36-40)
I20260812 06:18:58.741096  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000009 (ops 41-45)
I20260812 06:18:58.741134  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000010 (ops 46-50)
I20260812 06:18:58.741171  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000011 (ops 51-55)
I20260812 06:18:58.741212  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000012 (ops 56-60)
I20260812 06:18:58.741251  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000013 (ops 61-65)
I20260812 06:18:58.766242  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: LogGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:58.766738  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=3.181125
I20260812 06:18:58.785554  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7599,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:58.785964  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling LogGCOp(59cbef5f259b47e685b5b2a3429e7b42): free 12017983 bytes of WAL
I20260812 06:18:58.786163  3087 log_reader.cc:385] T 59cbef5f259b47e685b5b2a3429e7b42: removed 1 log segments from log reader
I20260812 06:18:58.786206  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000014 (ops 66-70)
I20260812 06:18:58.788573  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: LogGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:58.788861  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42): 450 bytes on disk
I20260812 06:18:58.789217  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.789646  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:58.807582  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.018s	user 0.003s	sys 0.014s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3544,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.808280  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:59.018955  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.210s	user 0.136s	sys 0.074s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":796,"lbm_read_time_us":14566,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34475,"lbm_writes_lt_1ms":643,"mutex_wait_us":297,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":77440,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:59.019630  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:18:59.074380  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.055s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19565,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.074966  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:59.089793  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.015s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.090481  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:59.271900  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.181s	user 0.112s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":837,"lbm_read_time_us":13451,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26678,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:18:59.272554  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=15.087375
I20260812 06:18:59.320852  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.048s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16820140,"delete_count":0,"lbm_write_time_us":21328,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:59.321439  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:59.341650  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.020s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5705,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.342140  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:59.505235  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.163s	user 0.103s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815668,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":924,"lbm_read_time_us":10332,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25931,"lbm_writes_lt_1ms":543,"mutex_wait_us":249,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:59.505970  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:18:59.558997  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.053s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23126,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.559490  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:59.569918  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.571808  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:59.741376  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.169s	user 0.105s	sys 0.060s 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":819,"lbm_read_time_us":10746,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26446,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:18:59.742014  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:18:59.788972  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.046s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20994,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.789441  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:18:59.801432  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.802138  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:18:59.946830  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.145s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":11462,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27312,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:18:59.947554  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=11.118625
I20260812 06:18:59.986155  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.038s	user 0.033s	sys 0.001s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16223,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.986997  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:00.003391  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5608,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.004374  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:00.134539  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.130s	user 0.103s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1831,"lbm_read_time_us":8935,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25958,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:19:00.135784  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=10.126437
I20260812 06:19:00.195942  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.060s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17469,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.196538  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:00.211704  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5663,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.212355  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:00.244966  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.030s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1694,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1547,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:00.245666  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling LogGCOp(59cbef5f259b47e685b5b2a3429e7b42): free 117302573 bytes of WAL
I20260812 06:19:00.246050  3087 log_reader.cc:385] T 59cbef5f259b47e685b5b2a3429e7b42: removed 12 log segments from log reader
I20260812 06:19:00.246155  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000015 (ops 71-75)
I20260812 06:19:00.246225  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000016 (ops 76-80)
I20260812 06:19:00.246286  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000017 (ops 81-85)
I20260812 06:19:00.246377  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000018 (ops 86-90)
I20260812 06:19:00.246456  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000019 (ops 91-95)
I20260812 06:19:00.246507  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000020 (ops 96-100)
I20260812 06:19:00.246585  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000021 (ops 101-104)
I20260812 06:19:00.246627  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000022 (ops 105-109)
I20260812 06:19:00.246673  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000023 (ops 110-114)
I20260812 06:19:00.246730  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000024 (ops 115-118)
I20260812 06:19:00.246780  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000025 (ops 119-123)
I20260812 06:19:00.246837  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000026 (ops 124-128)
I20260812 06:19:00.276750  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: LogGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.031s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:19:00.277228  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:00.293643  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.294251  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42): 472 bytes on disk
I20260812 06:19:00.294703  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.295325  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:00.451393  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.156s	user 0.095s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815803,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":373,"lbm_read_time_us":9812,"lbm_reads_lt_1ms":565,"lbm_write_time_us":29396,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":415488,"thread_start_us":121,"threads_started":1,"update_count":2500}
I20260812 06:19:00.452132  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:19:00.499325  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.047s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19879,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.499842  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:00.654490  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.154s	user 0.118s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713151,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":166,"lbm_read_time_us":10394,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25208,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:19:00.655325  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:19:00.712102  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.057s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25797,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.712646  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:00.725481  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.726074  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:00.920364  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.194s	user 0.121s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":11476,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32520,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:00.921067  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:19:00.973019  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.052s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19229,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.973608  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:00.985577  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.986091  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:01.149233  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.163s	user 0.124s	sys 0.030s 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":337,"lbm_read_time_us":9563,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30672,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:19:01.149943  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:19:01.204905  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.055s	user 0.020s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27065,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.205477  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:01.219691  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.220142  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:01.362293  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.142s	user 0.102s	sys 0.037s 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":306,"lbm_read_time_us":9050,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27638,"lbm_writes_lt_1ms":543,"mutex_wait_us":81,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:01.363024  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:19:01.413687  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24309,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.414208  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:01.424976  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.425485  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:01.574272  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.149s	user 0.109s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":11705,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28901,"lbm_writes_lt_1ms":543,"mutex_wait_us":97,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":2500}
I20260812 06:19:01.575052  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=11.118625
I20260812 06:19:01.613637  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.038s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17459,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:01.614853  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:01.630951  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6110,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.631414  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:01.655839  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushMRSOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.024s	user 0.022s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1568,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1459,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:01.656466  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling LogGCOp(59cbef5f259b47e685b5b2a3429e7b42): free 120553636 bytes of WAL
I20260812 06:19:01.656689  3087 log_reader.cc:385] T 59cbef5f259b47e685b5b2a3429e7b42: removed 12 log segments from log reader
I20260812 06:19:01.656754  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000027 (ops 129-132)
I20260812 06:19:01.656806  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000028 (ops 133-137)
I20260812 06:19:01.656864  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000029 (ops 138-142)
I20260812 06:19:01.656906  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000030 (ops 143-146)
I20260812 06:19:01.656945  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000031 (ops 147-151)
I20260812 06:19:01.656985  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000032 (ops 152-156)
I20260812 06:19:01.657023  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000033 (ops 157-161)
I20260812 06:19:01.657063  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000034 (ops 162-166)
I20260812 06:19:01.657101  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000035 (ops 167-171)
I20260812 06:19:01.657140  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000036 (ops 172-176)
I20260812 06:19:01.657179  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000037 (ops 177-181)
I20260812 06:19:01.657218  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000038 (ops 182-186)
I20260812 06:19:01.684791  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: LogGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:01.685261  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42): 472 bytes on disk
I20260812 06:19:01.685678  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: UndoDeltaBlockGCOp(59cbef5f259b47e685b5b2a3429e7b42) 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:19:01.686256  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=6.157687
I20260812 06:19:01.715032  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.029s	user 0.008s	sys 0.020s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":12426,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:01.715565  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling LogGCOp(59cbef5f259b47e685b5b2a3429e7b42): free 11564891 bytes of WAL
I20260812 06:19:01.715787  3087 log_reader.cc:385] T 59cbef5f259b47e685b5b2a3429e7b42: removed 1 log segments from log reader
I20260812 06:19:01.715845  3087 log.cc:1079] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: Deleting log segment in path: /tmp/dist-test-taskOOd6Yl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515531653122-2740-0/minicluster-data/ts-0-root/wals/59cbef5f259b47e685b5b2a3429e7b42/wal-000000039 (ops 187-190)
I20260812 06:19:01.719039  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: LogGCOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:01.719323  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:01.888633  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.169s	user 0.115s	sys 0.053s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918207,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":305,"lbm_read_time_us":10924,"lbm_reads_lt_1ms":665,"lbm_write_time_us":36664,"lbm_writes_lt_1ms":643,"mutex_wait_us":1109,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:19:01.889209  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=14.095187
I20260812 06:19:01.939795  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.050s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20034,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.940354  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=2.188937
I20260812 06:19:01.955878  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: FlushDeltaMemStoresOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6049,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.956364  3158 maintenance_manager.cc:419] P 4ba970ba991543f69ce1ee1854925716: Scheduling MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42): perf score=1.000000
I20260812 06:19:01.994699  2740 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.771s	user 1.786s	sys 0.143s
I20260812 06:19:02.050349  2740 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.001s	sys 0.000s
I20260812 06:19:02.050890  2740 tablet_server.cc:179] TabletServer@127.2.173.1:0 shutting down...
I20260812 06:19:02.094385  3087 maintenance_manager.cc:643] P 4ba970ba991543f69ce1ee1854925716: MajorDeltaCompactionOp(59cbef5f259b47e685b5b2a3429e7b42) complete. Timing: real 0.138s	user 0.098s	sys 0.040s 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":228,"lbm_read_time_us":11348,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28471,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:02.095211  2740 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:02.095541  2740 tablet_replica.cc:333] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716: stopping tablet replica
I20260812 06:19:02.095708  2740 raft_consensus.cc:2243] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.095896  2740 raft_consensus.cc:2272] T 59cbef5f259b47e685b5b2a3429e7b42 P 4ba970ba991543f69ce1ee1854925716 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.123306  2740 tablet_server.cc:196] TabletServer@127.2.173.1:0 shutdown complete.
I20260812 06:19:02.140892  2740 master.cc:562] Master@127.2.173.62:38075 shutting down...
I20260812 06:19:02.144289  2740 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.144436  2740 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.144518  2740 tablet_replica.cc:333] T 00000000000000000000000000000000 P c3cc966a8c5f4861a3ece1f6008b40b2: stopping tablet replica
I20260812 06:19:02.156829  2740 master.cc:584] Master@127.2.173.62:38075 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5255 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10583 ms total)

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