[==========] 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:19:36.921277  8854 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.165.190:35465
I20260812 06:19:36.922178  8854 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:19:36.922712  8854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.928292  8867 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:19:36.928371  8862 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:19:36.928465  8854 server_base.cc:1061] running on GCE node
W20260812 06:19:36.928575  8871 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:19:36.928998  8854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.929100  8854 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:19:36.929153  8854 hybrid_clock.cc:648] HybridClock initialized: now 1786515576929150 us; error 0 us; skew 500 ppm
I20260812 06:19:36.930727  8854 webserver.cc:533] Webserver started at http://127.8.165.190:36201/ using document root <none> and password file <none>
I20260812 06:19:36.931190  8854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.931247  8854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.931454  8854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.932936  8854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/master-0-root/instance:
uuid: "5721268c2c9241e4bbb2a7a5d6dc307a"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-bqcl"
I20260812 06:19:36.936087  8854 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:36.937906  8880 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:19:36.938783  8854 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:36.938885  8854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/master-0-root
uuid: "5721268c2c9241e4bbb2a7a5d6dc307a"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-bqcl"
I20260812 06:19:36.938962  8854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-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:19:36.979709  8854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.980352  8854 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:19:36.980511  8854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.987695  8854 rpc_server.cc:307] RPC server started. Bound to: 127.8.165.190:35465
I20260812 06:19:36.987701  8977 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.165.190:35465 every 8 connection(s)
I20260812 06:19:36.989852  8982 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:19:36.995185  8982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a: Bootstrap starting.
I20260812 06:19:36.997378  8982 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.998246  8982 log.cc:826] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:36.999748  8982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a: No bootstrap required, opened a new log
I20260812 06:19:37.002379  8982 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5721268c2c9241e4bbb2a7a5d6dc307a" member_type: VOTER }
I20260812 06:19:37.002545  8982 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:37.002607  8982 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5721268c2c9241e4bbb2a7a5d6dc307a, State: Initialized, Role: FOLLOWER
I20260812 06:19:37.003134  8982 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [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: "5721268c2c9241e4bbb2a7a5d6dc307a" member_type: VOTER }
I20260812 06:19:37.003263  8982 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:37.003306  8982 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:37.003389  8982 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:37.004055  8982 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5721268c2c9241e4bbb2a7a5d6dc307a" member_type: VOTER }
I20260812 06:19:37.004464  8982 leader_election.cc:304] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [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: 5721268c2c9241e4bbb2a7a5d6dc307a; no voters: 
I20260812 06:19:37.004755  8982 leader_election.cc:290] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:37.004873  8990 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:37.005079  8990 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 1 LEADER]: Becoming Leader. State: Replica: 5721268c2c9241e4bbb2a7a5d6dc307a, State: Running, Role: LEADER
I20260812 06:19:37.005525  8990 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [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: "5721268c2c9241e4bbb2a7a5d6dc307a" member_type: VOTER }
I20260812 06:19:37.005625  8982 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:37.007184  8996 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5721268c2c9241e4bbb2a7a5d6dc307a. Latest consensus state: current_term: 1 leader_uuid: "5721268c2c9241e4bbb2a7a5d6dc307a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5721268c2c9241e4bbb2a7a5d6dc307a" member_type: VOTER } }
I20260812 06:19:37.007275  8996 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:37.007242  8991 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5721268c2c9241e4bbb2a7a5d6dc307a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5721268c2c9241e4bbb2a7a5d6dc307a" member_type: VOTER } }
I20260812 06:19:37.007344  8991 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:37.007598  9007 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:37.007836  8854 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:37.009819  9007 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:37.013783  9007 catalog_manager.cc:1383] Generated new cluster ID: 12e923c20f7747e98158318a77914ddb
I20260812 06:19:37.013841  9007 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:37.021770  9007 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:37.022823  9007 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:37.034912  9007 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a: Generated new TSK 0
I20260812 06:19:37.035606  9007 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:37.040339  8854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:37.042728  9020 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:19:37.042800  9030 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:19:37.042835  9022 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:19:37.043054  8854 server_base.cc:1061] running on GCE node
I20260812 06:19:37.043222  8854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:37.043267  8854 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:19:37.043295  8854 hybrid_clock.cc:648] HybridClock initialized: now 1786515577043295 us; error 0 us; skew 500 ppm
I20260812 06:19:37.044103  8854 webserver.cc:533] Webserver started at http://127.8.165.129:33899/ using document root <none> and password file <none>
I20260812 06:19:37.044257  8854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:37.044309  8854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:37.044382  8854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:37.044756  8854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/instance:
uuid: "76e745c864ab4987910b86bb9e299510"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-bqcl"
I20260812 06:19:37.046206  8854 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:37.047130  9040 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:19:37.047351  8854 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:37.047417  8854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root
uuid: "76e745c864ab4987910b86bb9e299510"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-bqcl"
I20260812 06:19:37.047508  8854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-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:19:37.067008  8854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:37.067430  8854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:37.067894  8854 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:37.068746  8854 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:37.068800  8854 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.068845  8854 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:37.068876  8854 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.074962  8854 rpc_server.cc:307] RPC server started. Bound to: 127.8.165.129:45847
I20260812 06:19:37.075012  9150 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.165.129:45847 every 8 connection(s)
I20260812 06:19:37.087476  9151 heartbeater.cc:344] Connected to a master server at 127.8.165.190:35465
I20260812 06:19:37.087695  9151 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:37.088107  9151 heartbeater.cc:507] Master 127.8.165.190:35465 requested a full tablet report, sending...
I20260812 06:19:37.089509  8909 ts_manager.cc:194] Registered new tserver with Master: 76e745c864ab4987910b86bb9e299510 (127.8.165.129:45847)
I20260812 06:19:37.089892  8854 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014323041s
I20260812 06:19:37.091095  8909 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47720
I20260812 06:19:37.098114  8909 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47728:
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:19:37.111704  9096 tablet_service.cc:1511] Processing CreateTablet for tablet dff2ba5a264242f49d2b449225b36282 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bd96f8c302ba4912b798eb275aca42d8]), partition=
I20260812 06:19:37.112169  9096 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dff2ba5a264242f49d2b449225b36282. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:37.114352  9168 tablet_bootstrap.cc:492] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Bootstrap starting.
I20260812 06:19:37.115453  9168 tablet_bootstrap.cc:654] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:37.116657  9168 tablet_bootstrap.cc:492] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: No bootstrap required, opened a new log
I20260812 06:19:37.116752  9168 ts_tablet_manager.cc:1403] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:37.117231  9168 raft_consensus.cc:359] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "76e745c864ab4987910b86bb9e299510" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 45847 } }
I20260812 06:19:37.117347  9168 raft_consensus.cc:385] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:37.117386  9168 raft_consensus.cc:740] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 76e745c864ab4987910b86bb9e299510, State: Initialized, Role: FOLLOWER
I20260812 06:19:37.117554  9168 consensus_queue.cc:260] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [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: "76e745c864ab4987910b86bb9e299510" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 45847 } }
I20260812 06:19:37.117651  9168 raft_consensus.cc:399] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:37.117692  9168 raft_consensus.cc:493] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:37.117736  9168 raft_consensus.cc:3060] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:37.119062  9168 raft_consensus.cc:515] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "76e745c864ab4987910b86bb9e299510" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 45847 } }
I20260812 06:19:37.119207  9168 leader_election.cc:304] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [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: 76e745c864ab4987910b86bb9e299510; no voters: 
I20260812 06:19:37.119400  9168 leader_election.cc:290] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:37.119554  9173 raft_consensus.cc:2804] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:37.119786  9168 ts_tablet_manager.cc:1434] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:37.119832  9173 raft_consensus.cc:697] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 1 LEADER]: Becoming Leader. State: Replica: 76e745c864ab4987910b86bb9e299510, State: Running, Role: LEADER
I20260812 06:19:37.119990  9151 heartbeater.cc:499] Master 127.8.165.190:35465 was elected leader, sending a full tablet report...
I20260812 06:19:37.120379  9173 consensus_queue.cc:237] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [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: "76e745c864ab4987910b86bb9e299510" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 45847 } }
I20260812 06:19:37.123133  8909 catalog_manager.cc:5719] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 reported cstate change: term changed from 0 to 1, leader changed from <none> to 76e745c864ab4987910b86bb9e299510 (127.8.165.129). New cstate: current_term: 1 leader_uuid: "76e745c864ab4987910b86bb9e299510" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "76e745c864ab4987910b86bb9e299510" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 45847 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:37.187337  8854 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.021s	sys 0.006s
I20260812 06:19:37.326058  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushMRSOp(dff2ba5a264242f49d2b449225b36282): perf score=19.054940
I20260812 06:19:37.479439  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushMRSOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.153s	user 0.118s	sys 0.032s Metrics: {"bytes_written":12471592,"cfile_init":1,"compiler_manager_pool.queue_time_us":189,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":759,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38843,"lbm_writes_lt_1ms":771,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":269184,"thread_start_us":106,"threads_started":1,"update_count":1520}
I20260812 06:19:37.480593  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling LogGCOp(dff2ba5a264242f49d2b449225b36282): free 20743880 bytes of WAL
I20260812 06:19:37.480897  9049 log_reader.cc:385] T dff2ba5a264242f49d2b449225b36282: removed 2 log segments from log reader
I20260812 06:19:37.480962  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000001 (ops 1-6)
I20260812 06:19:37.481014  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000002 (ops 7-11)
I20260812 06:19:37.486150  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: LogGCOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.005s	user 0.002s	sys 0.003s Metrics: {}
I20260812 06:19:37.486594  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:37.531215  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.044s	user 0.004s	sys 0.016s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:19:37.531826  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling UndoDeltaBlockGCOp(dff2ba5a264242f49d2b449225b36282): 16821735 bytes on disk
I20260812 06:19:37.532337  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: UndoDeltaBlockGCOp(dff2ba5a264242f49d2b449225b36282) 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:37.532709  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:37.544512  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.544873  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:37.719550  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.175s	user 0.114s	sys 0.055s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405551,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":868,"lbm_read_time_us":13148,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":558,"lbm_write_time_us":31669,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":381,"threads_started":5,"update_count":2450}
I20260812 06:19:37.720185  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=10.126437
I20260812 06:19:37.755867  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15810,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.756438  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:37.774869  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.775352  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:37.888224  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.113s	user 0.092s	sys 0.021s 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":750,"lbm_read_time_us":8214,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22042,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:19:37.888721  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=11.118625
I20260812 06:19:37.915300  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.026s	user 0.018s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11400,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:37.915699  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:37.924742  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3194,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.925271  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:38.039124  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.114s	user 0.088s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":117,"lbm_read_time_us":7615,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22458,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":63872,"update_count":2000}
I20260812 06:19:38.039594  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=10.126437
I20260812 06:19:38.073724  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.034s	user 0.020s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12256,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.074183  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:38.088649  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.089203  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:38.209117  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.120s	user 0.107s	sys 0.012s 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":222,"lbm_read_time_us":6778,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23702,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:38.209636  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=10.126437
I20260812 06:19:38.255530  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.046s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":12249,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.256120  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:38.266105  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.266593  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:38.403712  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.137s	user 0.089s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":9247,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21858,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:19:38.404214  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=10.126437
I20260812 06:19:38.446996  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.043s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13678,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.447482  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:38.457959  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.458611  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:38.579319  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.121s	user 0.102s	sys 0.017s 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":206,"lbm_read_time_us":8473,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22718,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.579782  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=10.126437
I20260812 06:19:38.614464  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.035s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12976,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":1500}
I20260812 06:19:38.614879  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:38.624256  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.624658  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushMRSOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:38.654183  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushMRSOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.029s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1297,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2060,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:38.655105  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling LogGCOp(dff2ba5a264242f49d2b449225b36282): free 115943173 bytes of WAL
I20260812 06:19:38.655350  9049 log_reader.cc:385] T dff2ba5a264242f49d2b449225b36282: removed 11 log segments from log reader
I20260812 06:19:38.655401  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000003 (ops 12-16)
I20260812 06:19:38.655437  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000004 (ops 17-21)
I20260812 06:19:38.655471  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000005 (ops 22-26)
I20260812 06:19:38.655503  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000006 (ops 27-31)
I20260812 06:19:38.655532  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000007 (ops 32-36)
I20260812 06:19:38.655562  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000008 (ops 37-41)
I20260812 06:19:38.655592  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000009 (ops 42-46)
I20260812 06:19:38.655622  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000010 (ops 47-51)
I20260812 06:19:38.655652  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000011 (ops 52-56)
I20260812 06:19:38.655683  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000012 (ops 57-61)
I20260812 06:19:38.655714  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000013 (ops 62-66)
I20260812 06:19:38.675472  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: LogGCOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.020s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:38.675904  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:38.691115  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.015s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.691479  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling UndoDeltaBlockGCOp(dff2ba5a264242f49d2b449225b36282): 448 bytes on disk
I20260812 06:19:38.691843  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: UndoDeltaBlockGCOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.692252  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:38.704373  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.704751  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:38.865917  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.161s	user 0.116s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":356,"lbm_read_time_us":10986,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31614,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":68,"threads_started":1,"update_count":3000}
I20260812 06:19:38.866477  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:38.908237  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.040s	user 0.027s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17518,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.908694  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:38.924592  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5453,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.925017  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:39.076534  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.151s	user 0.100s	sys 0.048s 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":202,"lbm_read_time_us":10320,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28732,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:19:39.077162  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:39.116850  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.040s	user 0.016s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17562,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.117291  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:39.261188  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.144s	user 0.089s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":483,"lbm_read_time_us":9046,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22018,"lbm_writes_lt_1ms":443,"mutex_wait_us":273,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:19:39.261668  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:39.306794  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.045s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16370,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.307317  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:39.317766  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.318307  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:39.483287  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.165s	user 0.117s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":185,"lbm_read_time_us":9227,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25996,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:39.483775  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:39.528678  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.045s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20206,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.529280  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:39.546761  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.547281  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:39.689483  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.142s	user 0.099s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":567,"lbm_read_time_us":9849,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27754,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:19:39.690183  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:39.737673  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.047s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21860,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.738348  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:39.754364  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.754881  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:39.893594  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.139s	user 0.112s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":9006,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26803,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:39.894225  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:39.940897  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.046s	user 0.026s	sys 0.014s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18598,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.941354  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:39.952040  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3818,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.952488  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushMRSOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:39.977990  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushMRSOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.025s	user 0.020s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1196,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1428,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:39.978727  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling LogGCOp(dff2ba5a264242f49d2b449225b36282): free 133477428 bytes of WAL
I20260812 06:19:39.978958  9049 log_reader.cc:385] T dff2ba5a264242f49d2b449225b36282: removed 13 log segments from log reader
I20260812 06:19:39.979018  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000014 (ops 67-71)
I20260812 06:19:39.979063  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000015 (ops 72-76)
I20260812 06:19:39.979099  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000016 (ops 77-81)
I20260812 06:19:39.979122  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000017 (ops 82-86)
I20260812 06:19:39.979148  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000018 (ops 87-91)
I20260812 06:19:39.979174  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000019 (ops 92-96)
I20260812 06:19:39.979205  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000020 (ops 97-101)
I20260812 06:19:39.979235  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000021 (ops 102-106)
I20260812 06:19:39.979264  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000022 (ops 107-111)
I20260812 06:19:39.979292  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000023 (ops 112-116)
I20260812 06:19:39.979321  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000024 (ops 117-121)
I20260812 06:19:39.979351  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000025 (ops 122-126)
I20260812 06:19:39.979382  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000026 (ops 127-131)
I20260812 06:19:40.005447  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: LogGCOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:40.005913  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling UndoDeltaBlockGCOp(dff2ba5a264242f49d2b449225b36282): 482 bytes on disk
I20260812 06:19:40.006426  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: UndoDeltaBlockGCOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.007097  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=3.181125
I20260812 06:19:40.018648  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:40.019105  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:40.033257  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5118,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.033831  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:40.236153  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.202s	user 0.131s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020731,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1332,"lbm_read_time_us":12779,"lbm_reads_lt_1ms":774,"lbm_write_time_us":32138,"lbm_writes_lt_1ms":743,"mutex_wait_us":703,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":126,"threads_started":1,"update_count":3500}
I20260812 06:19:40.236884  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:40.287525  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.050s	user 0.034s	sys 0.014s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17413,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.288128  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:40.303120  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5900,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.303716  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:40.478543  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.175s	user 0.104s	sys 0.060s 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":118,"lbm_read_time_us":11793,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27739,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":44416,"update_count":2500}
I20260812 06:19:40.479089  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:40.521576  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.042s	user 0.020s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17190,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.522040  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:40.540113  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.018s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.540560  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:40.697399  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.157s	user 0.104s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1069,"lbm_read_time_us":10761,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25666,"lbm_writes_lt_1ms":543,"mutex_wait_us":526,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:40.700181  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=11.118625
I20260812 06:19:40.735987  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15356,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:40.736476  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:40.750730  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.751256  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:40.871562  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.120s	user 0.089s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":8926,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21574,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:40.872149  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=11.118625
I20260812 06:19:40.905277  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.033s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":13930,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:40.906004  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:40.920522  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3542,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.921043  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:41.036155  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.115s	user 0.106s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713266,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1650,"lbm_read_time_us":7216,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21070,"lbm_writes_lt_1ms":443,"mutex_wait_us":706,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:41.037050  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=10.126437
I20260812 06:19:41.069509  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.032s	user 0.014s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":11840,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.070017  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:41.080065  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.080628  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:41.199726  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.119s	user 0.100s	sys 0.018s 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":642,"lbm_read_time_us":8224,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22127,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:41.200148  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=10.126437
I20260812 06:19:41.251616  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.051s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13151,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.252096  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:41.266443  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.266909  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushMRSOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:41.308097  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushMRSOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.041s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1168,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1644,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:41.308878  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling LogGCOp(dff2ba5a264242f49d2b449225b36282): free 111786498 bytes of WAL
I20260812 06:19:41.309083  9049 log_reader.cc:385] T dff2ba5a264242f49d2b449225b36282: removed 11 log segments from log reader
I20260812 06:19:41.309139  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000027 (ops 132-136)
I20260812 06:19:41.309180  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000028 (ops 137-141)
I20260812 06:19:41.309211  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000029 (ops 142-146)
I20260812 06:19:41.309238  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000030 (ops 147-150)
I20260812 06:19:41.309267  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000031 (ops 151-155)
I20260812 06:19:41.309299  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000032 (ops 156-160)
I20260812 06:19:41.309330  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000033 (ops 161-165)
I20260812 06:19:41.309358  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000034 (ops 166-170)
I20260812 06:19:41.309384  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000035 (ops 171-174)
I20260812 06:19:41.309412  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000036 (ops 175-179)
I20260812 06:19:41.309443  9049 log.cc:1079] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/dff2ba5a264242f49d2b449225b36282/wal-000000037 (ops 180-184)
I20260812 06:19:41.332352  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: LogGCOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.023s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:19:41.332741  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=3.181125
I20260812 06:19:41.354719  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5737,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:41.355123  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=2.188937
I20260812 06:19:41.363662  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3245,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.364082  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:41.553273  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.189s	user 0.133s	sys 0.056s 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":126,"lbm_read_time_us":13511,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31741,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":80000,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:19:41.553861  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282): perf score=14.095187
I20260812 06:19:41.596652  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: FlushDeltaMemStoresOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.043s	user 0.031s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19119,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.597196  9152 maintenance_manager.cc:419] P 76e745c864ab4987910b86bb9e299510: Scheduling MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282): perf score=1.000000
I20260812 06:19:41.657505  8854 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.470s	user 1.639s	sys 0.107s
I20260812 06:19:41.713936  8854 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.002s	sys 0.000s
I20260812 06:19:41.714664  8854 tablet_server.cc:179] TabletServer@127.8.165.129:0 shutting down...
I20260812 06:19:41.719969  9049 maintenance_manager.cc:643] P 76e745c864ab4987910b86bb9e299510: MajorDeltaCompactionOp(dff2ba5a264242f49d2b449225b36282) complete. Timing: real 0.123s	user 0.088s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":731,"lbm_read_time_us":8907,"lbm_reads_lt_1ms":463,"lbm_write_time_us":20042,"lbm_writes_lt_1ms":443,"mutex_wait_us":260,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:19:41.720501  8854 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:41.722438  8854 tablet_replica.cc:333] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510: stopping tablet replica
I20260812 06:19:41.722676  8854 raft_consensus.cc:2243] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.722887  8854 raft_consensus.cc:2272] T dff2ba5a264242f49d2b449225b36282 P 76e745c864ab4987910b86bb9e299510 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.739001  8854 tablet_server.cc:196] TabletServer@127.8.165.129:0 shutdown complete.
I20260812 06:19:41.758378  8854 master.cc:562] Master@127.8.165.190:35465 shutting down...
I20260812 06:19:41.761315  8854 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.761461  8854 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.761536  8854 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5721268c2c9241e4bbb2a7a5d6dc307a: stopping tablet replica
I20260812 06:19:41.773505  8854 master.cc:584] Master@127.8.165.190:35465 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4920 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:41.852906  8854 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.165.190:40787
I20260812 06:19:41.853259  8854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.855036  9201 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:19:41.855140  9200 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:19:41.855188  9203 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:19:41.855240  8854 server_base.cc:1061] running on GCE node
I20260812 06:19:41.855381  8854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.855417  8854 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:19:41.855434  8854 hybrid_clock.cc:648] HybridClock initialized: now 1786515581855435 us; error 0 us; skew 500 ppm
I20260812 06:19:41.856205  8854 webserver.cc:533] Webserver started at http://127.8.165.190:37853/ using document root <none> and password file <none>
I20260812 06:19:41.856360  8854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.856406  8854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.856478  8854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.856837  8854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/master-0-root/instance:
uuid: "85de5739851d43569ea26c3297a54d29"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-bqcl"
I20260812 06:19:41.858251  8854 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:41.859100  9215 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:19:41.859308  8854 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:41.859377  8854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/master-0-root
uuid: "85de5739851d43569ea26c3297a54d29"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-bqcl"
I20260812 06:19:41.859447  8854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-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:19:41.868091  8854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.868381  8854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.872262  8854 rpc_server.cc:307] RPC server started. Bound to: 127.8.165.190:40787
I20260812 06:19:41.873656  9303 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.165.190:40787 every 8 connection(s)
I20260812 06:19:41.874091  9304 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:19:41.875710  9304 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29: Bootstrap starting.
I20260812 06:19:41.876381  9304 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.877260  9304 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29: No bootstrap required, opened a new log
I20260812 06:19:41.877594  9304 raft_consensus.cc:359] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "85de5739851d43569ea26c3297a54d29" member_type: VOTER }
I20260812 06:19:41.877674  9304 raft_consensus.cc:385] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.877696  9304 raft_consensus.cc:740] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 85de5739851d43569ea26c3297a54d29, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.877806  9304 consensus_queue.cc:260] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [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: "85de5739851d43569ea26c3297a54d29" member_type: VOTER }
I20260812 06:19:41.877895  9304 raft_consensus.cc:399] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.877919  9304 raft_consensus.cc:493] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.877948  9304 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.878605  9304 raft_consensus.cc:515] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "85de5739851d43569ea26c3297a54d29" member_type: VOTER }
I20260812 06:19:41.878719  9304 leader_election.cc:304] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [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: 85de5739851d43569ea26c3297a54d29; no voters: 
I20260812 06:19:41.878868  9304 leader_election.cc:290] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.878984  9307 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.879171  9307 raft_consensus.cc:697] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 1 LEADER]: Becoming Leader. State: Replica: 85de5739851d43569ea26c3297a54d29, State: Running, Role: LEADER
I20260812 06:19:41.879282  9304 sys_catalog.cc:565] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:41.879298  9307 consensus_queue.cc:237] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [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: "85de5739851d43569ea26c3297a54d29" member_type: VOTER }
I20260812 06:19:41.879719  9309 sys_catalog.cc:455] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "85de5739851d43569ea26c3297a54d29" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "85de5739851d43569ea26c3297a54d29" member_type: VOTER } }
I20260812 06:19:41.879743  9311 sys_catalog.cc:455] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 85de5739851d43569ea26c3297a54d29. Latest consensus state: current_term: 1 leader_uuid: "85de5739851d43569ea26c3297a54d29" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "85de5739851d43569ea26c3297a54d29" member_type: VOTER } }
I20260812 06:19:41.879810  9309 sys_catalog.cc:458] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.879827  9311 sys_catalog.cc:458] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.880054  9317 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:41.880772  9317 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:41.881004  8854 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:41.882469  9317 catalog_manager.cc:1383] Generated new cluster ID: dd1111e532bc45fc89f38ca794e1dfd6
I20260812 06:19:41.882520  9317 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:41.891440  9317 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:41.891908  9317 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:41.901820  9317 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29: Generated new TSK 0
I20260812 06:19:41.901973  9317 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:41.913060  8854 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.914724  9339 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:19:41.914798  9338 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:19:41.914849  9345 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:19:41.915014  8854 server_base.cc:1061] running on GCE node
I20260812 06:19:41.915134  8854 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.915165  8854 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:19:41.915179  8854 hybrid_clock.cc:648] HybridClock initialized: now 1786515581915179 us; error 0 us; skew 500 ppm
I20260812 06:19:41.915874  8854 webserver.cc:533] Webserver started at http://127.8.165.129:39061/ using document root <none> and password file <none>
I20260812 06:19:41.915995  8854 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.916033  8854 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.916092  8854 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.916419  8854 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/instance:
uuid: "a7537f68b7ab478781ad2ad1f7c7f0b1"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-bqcl"
I20260812 06:19:41.917703  8854 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:41.918520  9354 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:19:41.918759  8854 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:41.918825  8854 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root
uuid: "a7537f68b7ab478781ad2ad1f7c7f0b1"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-bqcl"
I20260812 06:19:41.918890  8854 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-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:19:41.928308  8854 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.928583  8854 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.928829  8854 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:41.929247  8854 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:41.929286  8854 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.929325  8854 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:41.929353  8854 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.933444  8854 rpc_server.cc:307] RPC server started. Bound to: 127.8.165.129:38483
I20260812 06:19:41.934514  9452 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.165.129:38483 every 8 connection(s)
I20260812 06:19:41.938542  9453 heartbeater.cc:344] Connected to a master server at 127.8.165.190:40787
I20260812 06:19:41.938632  9453 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:41.938814  9453 heartbeater.cc:507] Master 127.8.165.190:40787 requested a full tablet report, sending...
I20260812 06:19:41.939402  9242 ts_manager.cc:194] Registered new tserver with Master: a7537f68b7ab478781ad2ad1f7c7f0b1 (127.8.165.129:38483)
I20260812 06:19:41.939786  8854 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005555454s
I20260812 06:19:41.940258  9242 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50790
I20260812 06:19:41.946065  9242 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50792:
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:19:41.953969  9399 tablet_service.cc:1511] Processing CreateTablet for tablet a0438fc572784f0ca120849734363b00 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d7b219086e6f4113bc6a7277376f3adf]), partition=
I20260812 06:19:41.954231  9399 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a0438fc572784f0ca120849734363b00. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:41.955960  9481 tablet_bootstrap.cc:492] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Bootstrap starting.
I20260812 06:19:41.956972  9481 tablet_bootstrap.cc:654] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.957844  9481 tablet_bootstrap.cc:492] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: No bootstrap required, opened a new log
I20260812 06:19:41.957914  9481 ts_tablet_manager.cc:1403] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:41.958287  9481 raft_consensus.cc:359] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7537f68b7ab478781ad2ad1f7c7f0b1" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 38483 } }
I20260812 06:19:41.958371  9481 raft_consensus.cc:385] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.958397  9481 raft_consensus.cc:740] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a7537f68b7ab478781ad2ad1f7c7f0b1, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.958503  9481 consensus_queue.cc:260] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [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: "a7537f68b7ab478781ad2ad1f7c7f0b1" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 38483 } }
I20260812 06:19:41.958606  9481 raft_consensus.cc:399] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.958638  9481 raft_consensus.cc:493] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.958673  9481 raft_consensus.cc:3060] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.959322  9481 raft_consensus.cc:515] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7537f68b7ab478781ad2ad1f7c7f0b1" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 38483 } }
I20260812 06:19:41.959467  9481 leader_election.cc:304] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [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: a7537f68b7ab478781ad2ad1f7c7f0b1; no voters: 
I20260812 06:19:41.959654  9481 leader_election.cc:290] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.959756  9484 raft_consensus.cc:2804] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.959936  9484 raft_consensus.cc:697] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 1 LEADER]: Becoming Leader. State: Replica: a7537f68b7ab478781ad2ad1f7c7f0b1, State: Running, Role: LEADER
I20260812 06:19:41.960021  9481 ts_tablet_manager.cc:1434] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:41.960031  9453 heartbeater.cc:499] Master 127.8.165.190:40787 was elected leader, sending a full tablet report...
I20260812 06:19:41.960127  9484 consensus_queue.cc:237] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [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: "a7537f68b7ab478781ad2ad1f7c7f0b1" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 38483 } }
I20260812 06:19:41.961316  9242 catalog_manager.cc:5719] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 reported cstate change: term changed from 0 to 1, leader changed from <none> to a7537f68b7ab478781ad2ad1f7c7f0b1 (127.8.165.129). New cstate: current_term: 1 leader_uuid: "a7537f68b7ab478781ad2ad1f7c7f0b1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7537f68b7ab478781ad2ad1f7c7f0b1" member_type: VOTER last_known_addr { host: "127.8.165.129" port: 38483 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:42.015071  8854 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.013s	sys 0.009s
I20260812 06:19:42.185243  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushMRSOp(a0438fc572784f0ca120849734363b00): perf score=23.023690
I20260812 06:19:42.336176  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushMRSOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.151s	user 0.109s	sys 0.036s Metrics: {"bytes_written":9805020,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":768,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38464,"lbm_writes_lt_1ms":796,"mutex_wait_us":1944,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":6912,"update_count":1195}
I20260812 06:19:42.336781  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling LogGCOp(a0438fc572784f0ca120849734363b00): free 20743880 bytes of WAL
I20260812 06:19:42.337005  9363 log_reader.cc:385] T a0438fc572784f0ca120849734363b00: removed 2 log segments from log reader
I20260812 06:19:42.337055  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000001 (ops 1-6)
I20260812 06:19:42.337086  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000002 (ops 7-11)
I20260812 06:19:42.340950  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: LogGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:42.341313  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00): 20513814 bytes on disk
I20260812 06:19:42.341764  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.342254  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=1.196750
I20260812 06:19:42.364323  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.022s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2502679,"delete_count":0,"lbm_write_time_us":2423,"lbm_writes_lt_1ms":64,"reinsert_count":0,"update_count":305}
I20260812 06:19:42.364730  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:42.378671  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.379065  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:42.525343  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.146s	user 0.090s	sys 0.056s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20713352,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":873,"lbm_read_time_us":10522,"lbm_reads_lt_1ms":469,"lbm_write_time_us":24247,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":353,"threads_started":5,"update_count":2000}
I20260812 06:19:42.525873  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:42.558416  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.032s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13753,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.558890  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:42.573544  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.573988  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:42.689538  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.115s	user 0.089s	sys 0.026s 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":200,"lbm_read_time_us":8570,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21003,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:19:42.690032  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:42.731284  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.041s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15357,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.731925  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:42.827957  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.096s	user 0.075s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610743,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":505,"lbm_read_time_us":7351,"lbm_reads_lt_1ms":363,"lbm_write_time_us":16972,"lbm_writes_lt_1ms":343,"mutex_wait_us":21,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":1500}
I20260812 06:19:42.828473  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:42.871565  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.043s	user 0.041s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17417,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.871995  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:42.881594  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.009s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3467,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.882155  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:43.007663  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.125s	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":225,"lbm_read_time_us":8173,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20820,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:43.008286  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:43.049343  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.041s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14559,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.049788  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:43.064316  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.064821  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:43.190773  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.126s	user 0.112s	sys 0.013s 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":563,"lbm_read_time_us":9376,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22953,"lbm_writes_lt_1ms":443,"mutex_wait_us":261,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:19:43.191241  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:43.223389  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.032s	user 0.008s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11558,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.223933  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:43.324877  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.101s	user 0.087s	sys 0.012s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":581,"lbm_read_time_us":6853,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17958,"lbm_writes_lt_1ms":343,"mutex_wait_us":39,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":1500}
I20260812 06:19:43.325402  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:43.364848  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.039s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16388,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.365339  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:43.374938  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.009s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.375471  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:43.494733  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.119s	user 0.093s	sys 0.026s 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":514,"lbm_read_time_us":8028,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21741,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:19:43.495236  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:43.536127  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.041s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13927,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.536644  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:43.546356  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.546864  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushMRSOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:43.574448  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushMRSOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.027s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1212,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1363,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:43.575103  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling LogGCOp(a0438fc572784f0ca120849734363b00): free 121006438 bytes of WAL
I20260812 06:19:43.575323  9363 log_reader.cc:385] T a0438fc572784f0ca120849734363b00: removed 12 log segments from log reader
I20260812 06:19:43.575371  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000003 (ops 12-16)
I20260812 06:19:43.575407  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000004 (ops 17-20)
I20260812 06:19:43.575439  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000005 (ops 21-25)
I20260812 06:19:43.575471  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000006 (ops 26-30)
I20260812 06:19:43.575501  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000007 (ops 31-35)
I20260812 06:19:43.575524  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000008 (ops 36-40)
I20260812 06:19:43.575555  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000009 (ops 41-45)
I20260812 06:19:43.575587  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000010 (ops 46-50)
I20260812 06:19:43.575616  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000011 (ops 51-55)
I20260812 06:19:43.575645  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000012 (ops 56-60)
I20260812 06:19:43.575675  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000013 (ops 61-65)
I20260812 06:19:43.575706  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000014 (ops 66-70)
I20260812 06:19:43.596872  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: LogGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:43.597241  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00): 471 bytes on disk
I20260812 06:19:43.597683  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.598173  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=3.181125
I20260812 06:19:43.616871  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.019s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7034,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.617240  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:43.626024  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3452,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.626361  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:43.783983  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.157s	user 0.110s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1212,"lbm_read_time_us":10250,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33053,"lbm_writes_lt_1ms":643,"mutex_wait_us":657,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:19:43.784493  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=14.095187
I20260812 06:19:43.834916  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.050s	user 0.012s	sys 0.036s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19750,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.835458  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:43.848791  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.849408  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:43.991662  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.142s	user 0.116s	sys 0.023s 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":499,"lbm_read_time_us":9042,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26862,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:19:43.992318  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=11.118625
I20260812 06:19:44.019605  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.027s	user 0.014s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11336,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.020248  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.033227  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4676,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.033708  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:44.146391  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.113s	user 0.100s	sys 0.012s 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":1120,"lbm_read_time_us":7406,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21889,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:44.147403  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:44.182989  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.035s	user 0.025s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11742,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.183545  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.197782  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.198282  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:44.312434  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.114s	user 0.089s	sys 0.025s 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":301,"lbm_read_time_us":7616,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21493,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:19:44.312942  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:44.360244  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.047s	user 0.020s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17442,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.360702  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.370199  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.009s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.370545  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:44.500751  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.130s	user 0.088s	sys 0.042s 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":161,"lbm_read_time_us":10050,"lbm_reads_lt_1ms":472,"lbm_write_time_us":18866,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:19:44.501214  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:44.544438  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.043s	user 0.029s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13306,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.544895  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.554822  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.555306  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:44.674729  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.119s	user 0.095s	sys 0.023s 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":463,"lbm_read_time_us":9729,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21596,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:19:44.675261  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:44.717609  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.042s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15533,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.718117  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.732424  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.732915  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:44.840245  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.107s	user 0.095s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":89,"lbm_read_time_us":7708,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19866,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:19:44.840770  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:44.888679  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.048s	user 0.039s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16390,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.889156  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.899005  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.899370  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushMRSOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:44.937037  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushMRSOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.038s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1173,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1368,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:44.937623  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling LogGCOp(a0438fc572784f0ca120849734363b00): free 133024390 bytes of WAL
I20260812 06:19:44.937830  9363 log_reader.cc:385] T a0438fc572784f0ca120849734363b00: removed 13 log segments from log reader
I20260812 06:19:44.937878  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000015 (ops 71-75)
I20260812 06:19:44.937906  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000016 (ops 76-80)
I20260812 06:19:44.937937  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000017 (ops 81-85)
I20260812 06:19:44.937971  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000018 (ops 86-90)
I20260812 06:19:44.937992  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000019 (ops 91-95)
I20260812 06:19:44.938032  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000020 (ops 96-100)
I20260812 06:19:44.938066  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000021 (ops 101-105)
I20260812 06:19:44.938097  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000022 (ops 106-110)
I20260812 06:19:44.938154  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000023 (ops 111-114)
I20260812 06:19:44.938189  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000024 (ops 115-119)
I20260812 06:19:44.938206  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000025 (ops 120-124)
I20260812 06:19:44.938237  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000026 (ops 125-129)
I20260812 06:19:44.938268  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000027 (ops 130-134)
I20260812 06:19:44.959132  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: LogGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:44.959551  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00): 482 bytes on disk
I20260812 06:19:44.960003  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.960636  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.982115  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.021s	user 0.003s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.982543  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:44.997380  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.015s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.997893  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:45.180825  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.183s	user 0.115s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":532,"lbm_read_time_us":11879,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29820,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":83456,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:19:45.181375  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=14.095187
I20260812 06:19:45.222716  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17599,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.223296  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:45.374771  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.151s	user 0.084s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":275,"lbm_read_time_us":10029,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21318,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.375248  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=14.095187
I20260812 06:19:45.416939  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.042s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18128,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.417455  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:45.433511  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.433979  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:45.604032  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.170s	user 0.103s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":11409,"lbm_reads_lt_1ms":564,"lbm_write_time_us":24865,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:45.604568  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=14.095187
I20260812 06:19:45.654621  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.050s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19473,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.655092  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:45.666597  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.667092  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:45.811744  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.144s	user 0.110s	sys 0.033s 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":853,"lbm_read_time_us":10198,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27701,"lbm_writes_lt_1ms":543,"mutex_wait_us":235,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:19:45.812309  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=11.118625
I20260812 06:19:45.847417  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.035s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15028,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:45.847911  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:45.869071  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.021s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4552,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.869520  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:45.878690  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.879076  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:46.026175  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.147s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":282,"lbm_read_time_us":11180,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27685,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:46.026741  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=11.118625
I20260812 06:19:46.055240  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":11829,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.055889  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:46.068521  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3950,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.068946  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:46.189865  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.121s	user 0.104s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713262,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":116,"lbm_read_time_us":7961,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23201,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:19:46.190467  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:46.229121  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.038s	user 0.018s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12347,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.229631  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:46.239068  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.239558  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushMRSOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:46.273842  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushMRSOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.034s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1114,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1704,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:46.274539  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling LogGCOp(a0438fc572784f0ca120849734363b00): free 120553636 bytes of WAL
I20260812 06:19:46.274770  9363 log_reader.cc:385] T a0438fc572784f0ca120849734363b00: removed 12 log segments from log reader
I20260812 06:19:46.274842  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000028 (ops 135-138)
I20260812 06:19:46.274889  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000029 (ops 139-143)
I20260812 06:19:46.274919  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000030 (ops 144-148)
I20260812 06:19:46.274948  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000031 (ops 149-152)
I20260812 06:19:46.274981  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000032 (ops 153-157)
I20260812 06:19:46.275009  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000033 (ops 158-162)
I20260812 06:19:46.275038  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000034 (ops 163-167)
I20260812 06:19:46.275074  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000035 (ops 168-172)
I20260812 06:19:46.275105  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000036 (ops 173-177)
I20260812 06:19:46.275136  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000037 (ops 178-182)
I20260812 06:19:46.275167  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000038 (ops 183-187)
I20260812 06:19:46.275194  9363 log.cc:1079] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: Deleting log segment in path: /tmp/dist-test-taskDK6RQi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576911418-8854-0/minicluster-data/ts-0-root/wals/a0438fc572784f0ca120849734363b00/wal-000000039 (ops 188-192)
I20260812 06:19:46.298998  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: LogGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:46.299448  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:46.312956  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.313336  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00): 462 bytes on disk
I20260812 06:19:46.313691  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: UndoDeltaBlockGCOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.314255  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=2.188937
I20260812 06:19:46.323812  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.324182  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:46.439949  8854 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.425s	user 1.661s	sys 0.132s
I20260812 06:19:46.475107  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.151s	user 0.121s	sys 0.029s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918335,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":12906,"lbm_reads_lt_1ms":670,"lbm_write_time_us":27922,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":3000}
I20260812 06:19:46.475571  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00): perf score=10.126437
I20260812 06:19:46.503759  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: FlushDeltaMemStoresOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.028s	user 0.013s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":11378,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:19:46.504338  9454 maintenance_manager.cc:419] P a7537f68b7ab478781ad2ad1f7c7f0b1: Scheduling MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00): perf score=1.000000
I20260812 06:19:46.511209  8854 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.002s	sys 0.000s
I20260812 06:19:46.511636  8854 tablet_server.cc:179] TabletServer@127.8.165.129:0 shutting down...
I20260812 06:19:46.590247  9363 maintenance_manager.cc:643] P a7537f68b7ab478781ad2ad1f7c7f0b1: MajorDeltaCompactionOp(a0438fc572784f0ca120849734363b00) complete. Timing: real 0.086s	user 0.074s	sys 0.012s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":395,"lbm_read_time_us":6437,"lbm_reads_lt_1ms":367,"lbm_write_time_us":15639,"lbm_writes_lt_1ms":343,"mutex_wait_us":63,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":81152,"update_count":1500}
I20260812 06:19:46.591073  8854 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:46.591269  8854 tablet_replica.cc:333] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1: stopping tablet replica
I20260812 06:19:46.591387  8854 raft_consensus.cc:2243] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:46.591542  8854 raft_consensus.cc:2272] T a0438fc572784f0ca120849734363b00 P a7537f68b7ab478781ad2ad1f7c7f0b1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:46.604696  8854 tablet_server.cc:196] TabletServer@127.8.165.129:0 shutdown complete.
I20260812 06:19:46.622179  8854 master.cc:562] Master@127.8.165.190:40787 shutting down...
I20260812 06:19:46.625540  8854 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:46.625712  8854 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:46.625790  8854 tablet_replica.cc:333] T 00000000000000000000000000000000 P 85de5739851d43569ea26c3297a54d29: stopping tablet replica
I20260812 06:19:46.639097  8854 master.cc:584] Master@127.8.165.190:40787 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4870 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9792 ms total)

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