[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:08.988750 12938 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.162.190:46335
I20260812 06:18:08.989750 12938 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:08.990393 12938 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.996501 12946 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.996547 12944 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:08.996728 12938 server_base.cc:1061] running on GCE node
W20260812 06:18:08.996780 12943 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:08.997284 12938 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.997399 12938 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:08.997448 12938 hybrid_clock.cc:648] HybridClock initialized: now 1786515488997446 us; error 0 us; skew 500 ppm
I20260812 06:18:08.999492 12938 webserver.cc:533] Webserver started at http://127.12.162.190:36167/ using document root <none> and password file <none>
I20260812 06:18:09.000057 12938 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:09.000129 12938 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:09.000365 12938 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:09.002091 12938 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/master-0-root/instance:
uuid: "8523bc00f9a4459abdd30528ab0286be"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-69rg"
I20260812 06:18:09.005564 12938 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:09.007740 12952 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:09.008805 12938 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:09.008913 12938 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/master-0-root
uuid: "8523bc00f9a4459abdd30528ab0286be"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-69rg"
I20260812 06:18:09.009052 12938 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:09.031567 12938 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:09.032258 12938 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:09.032449 12938 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:09.040294 13015 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.162.190:46335 every 8 connection(s)
I20260812 06:18:09.040297 12938 rpc_server.cc:307] RPC server started. Bound to: 127.12.162.190:46335
I20260812 06:18:09.042703 13016 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:09.048012 13016 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be: Bootstrap starting.
I20260812 06:18:09.050380 13016 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:09.051306 13016 log.cc:826] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:09.052990 13016 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be: No bootstrap required, opened a new log
I20260812 06:18:09.055821 13016 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8523bc00f9a4459abdd30528ab0286be" member_type: VOTER }
I20260812 06:18:09.056111 13016 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:09.056245 13016 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8523bc00f9a4459abdd30528ab0286be, State: Initialized, Role: FOLLOWER
I20260812 06:18:09.056970 13016 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [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: "8523bc00f9a4459abdd30528ab0286be" member_type: VOTER }
I20260812 06:18:09.057138 13016 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:09.057242 13016 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:09.057394 13016 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:09.058427 13016 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8523bc00f9a4459abdd30528ab0286be" member_type: VOTER }
I20260812 06:18:09.058943 13016 leader_election.cc:304] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [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: 8523bc00f9a4459abdd30528ab0286be; no voters: 
I20260812 06:18:09.059343 13016 leader_election.cc:290] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:09.059603 13019 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:09.059902 13019 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 1 LEADER]: Becoming Leader. State: Replica: 8523bc00f9a4459abdd30528ab0286be, State: Running, Role: LEADER
I20260812 06:18:09.060431 13019 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [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: "8523bc00f9a4459abdd30528ab0286be" member_type: VOTER }
I20260812 06:18:09.060475 13016 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:09.062927 13023 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8523bc00f9a4459abdd30528ab0286be. Latest consensus state: current_term: 1 leader_uuid: "8523bc00f9a4459abdd30528ab0286be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8523bc00f9a4459abdd30528ab0286be" member_type: VOTER } }
I20260812 06:18:09.062935 13020 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8523bc00f9a4459abdd30528ab0286be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8523bc00f9a4459abdd30528ab0286be" member_type: VOTER } }
I20260812 06:18:09.063081 13020 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:09.063076 13023 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:09.063060 12938 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:09.065258 13037 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:09.065352 13037 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:09.065423 13038 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:09.066299 13038 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:09.071286 13038 catalog_manager.cc:1383] Generated new cluster ID: 8411be45ef8143228f2d7dcd6468d5c4
I20260812 06:18:09.071367 13038 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:09.092236 13038 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:09.093175 13038 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:09.098707 13038 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be: Generated new TSK 0
I20260812 06:18:09.099320 13038 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:09.128334 12938 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:09.131520 13043 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:09.131520 13042 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:09.131650 12938 server_base.cc:1061] running on GCE node
W20260812 06:18:09.131538 13045 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:09.131973 12938 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:09.132040 12938 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:09.132064 12938 hybrid_clock.cc:648] HybridClock initialized: now 1786515489132064 us; error 0 us; skew 500 ppm
I20260812 06:18:09.133028 12938 webserver.cc:533] Webserver started at http://127.12.162.129:43149/ using document root <none> and password file <none>
I20260812 06:18:09.133203 12938 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:09.133260 12938 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:09.133330 12938 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:09.133772 12938 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/instance:
uuid: "d3ac0eedbe074e778a5d8eddcf8d2834"
format_stamp: "Formatted at 2026-08-12 06:18:09 on dist-test-slave-69rg"
I20260812 06:18:09.135676 12938 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:09.136842 13050 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:09.137171 12938 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:09.137245 12938 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root
uuid: "d3ac0eedbe074e778a5d8eddcf8d2834"
format_stamp: "Formatted at 2026-08-12 06:18:09 on dist-test-slave-69rg"
I20260812 06:18:09.137338 12938 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:09.165006 12938 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:09.165534 12938 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:09.166116 12938 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:09.167016 12938 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:09.167069 12938 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:09.167135 12938 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:09.167186 12938 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:09.174142 12938 rpc_server.cc:307] RPC server started. Bound to: 127.12.162.129:44893
I20260812 06:18:09.174198 13129 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.162.129:44893 every 8 connection(s)
I20260812 06:18:09.187930 13130 heartbeater.cc:344] Connected to a master server at 127.12.162.190:46335
I20260812 06:18:09.188253 13130 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:09.188771 13130 heartbeater.cc:507] Master 127.12.162.190:46335 requested a full tablet report, sending...
I20260812 06:18:09.190368 12972 ts_manager.cc:194] Registered new tserver with Master: d3ac0eedbe074e778a5d8eddcf8d2834 (127.12.162.129:44893)
I20260812 06:18:09.190623 12938 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015759883s
I20260812 06:18:09.191859 12972 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51906
I20260812 06:18:09.201184 12972 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51916:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:09.217242 13086 tablet_service.cc:1511] Processing CreateTablet for tablet e9b4fd55129f4d01a298f38d7b319747 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e679fc3f48ee45ecab567172b08434f8]), partition=
I20260812 06:18:09.217777 13086 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e9b4fd55129f4d01a298f38d7b319747. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:09.220078 13143 tablet_bootstrap.cc:492] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Bootstrap starting.
I20260812 06:18:09.221561 13143 tablet_bootstrap.cc:654] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:09.222887 13143 tablet_bootstrap.cc:492] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: No bootstrap required, opened a new log
I20260812 06:18:09.222975 13143 ts_tablet_manager.cc:1403] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:09.223551 13143 raft_consensus.cc:359] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3ac0eedbe074e778a5d8eddcf8d2834" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 44893 } }
I20260812 06:18:09.223660 13143 raft_consensus.cc:385] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:09.223685 13143 raft_consensus.cc:740] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d3ac0eedbe074e778a5d8eddcf8d2834, State: Initialized, Role: FOLLOWER
I20260812 06:18:09.223842 13143 consensus_queue.cc:260] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [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: "d3ac0eedbe074e778a5d8eddcf8d2834" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 44893 } }
I20260812 06:18:09.223935 13143 raft_consensus.cc:399] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:09.223963 13143 raft_consensus.cc:493] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:09.224076 13143 raft_consensus.cc:3060] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:09.225092 13143 raft_consensus.cc:515] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3ac0eedbe074e778a5d8eddcf8d2834" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 44893 } }
I20260812 06:18:09.225260 13143 leader_election.cc:304] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [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: d3ac0eedbe074e778a5d8eddcf8d2834; no voters: 
I20260812 06:18:09.225502 13143 leader_election.cc:290] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:09.225658 13145 raft_consensus.cc:2804] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:09.225911 13145 raft_consensus.cc:697] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 1 LEADER]: Becoming Leader. State: Replica: d3ac0eedbe074e778a5d8eddcf8d2834, State: Running, Role: LEADER
I20260812 06:18:09.225912 13143 ts_tablet_manager.cc:1434] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:09.226100 13145 consensus_queue.cc:237] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [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: "d3ac0eedbe074e778a5d8eddcf8d2834" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 44893 } }
I20260812 06:18:09.226244 13130 heartbeater.cc:499] Master 127.12.162.190:46335 was elected leader, sending a full tablet report...
I20260812 06:18:09.229018 12972 catalog_manager.cc:5719] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 reported cstate change: term changed from 0 to 1, leader changed from <none> to d3ac0eedbe074e778a5d8eddcf8d2834 (127.12.162.129). New cstate: current_term: 1 leader_uuid: "d3ac0eedbe074e778a5d8eddcf8d2834" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3ac0eedbe074e778a5d8eddcf8d2834" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 44893 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:09.293965 12938 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.017s	sys 0.008s
I20260812 06:18:09.425357 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747): perf score=19.054940
I20260812 06:18:09.616853 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.191s	user 0.132s	sys 0.045s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":250,"delete_count":0,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":930,"drs_written":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46002,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":131,"threads_started":1,"update_count":1500}
I20260812 06:18:09.618189 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling LogGCOp(e9b4fd55129f4d01a298f38d7b319747): free 20743880 bytes of WAL
I20260812 06:18:09.618495 13056 log_reader.cc:385] T e9b4fd55129f4d01a298f38d7b319747: removed 2 log segments from log reader
I20260812 06:18:09.618556 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000001 (ops 1-6)
I20260812 06:18:09.618605 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000002 (ops 7-11)
I20260812 06:18:09.623703 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: LogGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:09.624138 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747): 16411394 bytes on disk
I20260812 06:18:09.624756 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.625588 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:09.659116 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.033s	user 0.010s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.659585 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:09.670387 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.670835 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:09.837716 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.167s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":597,"lbm_read_time_us":11684,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27773,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":317,"threads_started":5,"update_count":2500}
I20260812 06:18:09.839062 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:09.877979 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.039s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17330,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.881793 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:09.898134 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6590,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.898880 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:10.029143 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.130s	user 0.104s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1836,"lbm_read_time_us":7726,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26699,"lbm_writes_lt_1ms":443,"mutex_wait_us":262,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.030550 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:10.078625 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.048s	user 0.026s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20431,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.079276 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:10.092760 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.013s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.093358 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:10.210646 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.117s	user 0.081s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":8402,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22580,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:18:10.211228 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:10.256840 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.045s	user 0.018s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20628,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.257346 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:10.268739 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.269183 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:10.390045 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.121s	user 0.110s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":8796,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23639,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:10.390633 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:10.436555 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.046s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18154,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.437079 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:10.449609 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.450157 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:10.599150 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.149s	user 0.090s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":9862,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25081,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:10.599995 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=11.118625
I20260812 06:18:10.630086 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.030s	user 0.026s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12782,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:10.631018 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:10.657981 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.027s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5401,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.658630 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:10.669572 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.670109 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:10.817925 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.148s	user 0.121s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":378,"lbm_read_time_us":10543,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28366,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:10.818679 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:10.854534 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.035s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15496,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.855163 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:10.869455 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5496,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.869968 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:10.899744 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1254,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1598,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:10.900552 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling LogGCOp(e9b4fd55129f4d01a298f38d7b319747): free 120553374 bytes of WAL
I20260812 06:18:10.900810 13056 log_reader.cc:385] T e9b4fd55129f4d01a298f38d7b319747: removed 12 log segments from log reader
I20260812 06:18:10.900882 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000003 (ops 12-16)
I20260812 06:18:10.900920 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000004 (ops 17-20)
I20260812 06:18:10.900952 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000005 (ops 21-25)
I20260812 06:18:10.900998 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000006 (ops 26-30)
I20260812 06:18:10.901036 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000007 (ops 31-35)
I20260812 06:18:10.901072 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000008 (ops 36-40)
I20260812 06:18:10.901117 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000009 (ops 41-45)
I20260812 06:18:10.901170 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000010 (ops 46-50)
I20260812 06:18:10.901226 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000011 (ops 51-54)
I20260812 06:18:10.901280 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000012 (ops 55-59)
I20260812 06:18:10.901330 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000013 (ops 60-64)
I20260812 06:18:10.901383 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000014 (ops 65-69)
I20260812 06:18:10.927426 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: LogGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:10.927884 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=6.157687
I20260812 06:18:10.960570 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.033s	user 0.013s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9619,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:10.961404 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747): 472 bytes on disk
I20260812 06:18:10.962024 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.962581 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:10.970479 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.008s	user 0.004s	sys 0.001s Metrics: {"bytes_written":1805256,"delete_count":0,"lbm_write_time_us":1745,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:18:10.970957 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.196750
I20260812 06:18:10.980443 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":3269,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:18:10.981117 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:11.182358 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.201s	user 0.141s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979776,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":624,"lbm_read_time_us":14341,"lbm_reads_lt_1ms":775,"lbm_write_time_us":34722,"lbm_writes_lt_1ms":743,"mutex_wait_us":86,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:11.183135 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=14.095187
I20260812 06:18:11.240427 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.057s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24344,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.240962 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:11.257956 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.258625 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:11.438588 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.180s	user 0.088s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":13072,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29879,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:11.439253 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=14.095187
I20260812 06:18:11.497970 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.059s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19709,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.498525 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:11.509007 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.509434 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:11.692780 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.183s	user 0.144s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":870,"lbm_read_time_us":12290,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30063,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:18:11.693413 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=14.095187
I20260812 06:18:11.757069 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.063s	user 0.015s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19060,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.758137 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:11.900193 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.142s	user 0.089s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":678,"lbm_read_time_us":9977,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22229,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:11.900846 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=11.118625
I20260812 06:18:11.945672 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.045s	user 0.023s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18403,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:11.946349 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:11.961854 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4941,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.962488 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:12.104614 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.142s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":933,"lbm_read_time_us":10098,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27395,"lbm_writes_lt_1ms":443,"mutex_wait_us":1740,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:12.105479 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:12.154457 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.048s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24046,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.155248 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:12.174458 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.175042 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:12.317734 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.143s	user 0.086s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1121,"lbm_read_time_us":10492,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27339,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:12.318548 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:12.373039 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.054s	user 0.033s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18191,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:12.373908 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:12.392123 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6904,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.393384 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:12.431013 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.037s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1607,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1442,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:12.431962 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling LogGCOp(e9b4fd55129f4d01a298f38d7b319747): free 120100335 bytes of WAL
I20260812 06:18:12.432276 13056 log_reader.cc:385] T e9b4fd55129f4d01a298f38d7b319747: removed 12 log segments from log reader
I20260812 06:18:12.432355 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000015 (ops 70-74)
I20260812 06:18:12.432412 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000016 (ops 75-78)
I20260812 06:18:12.432471 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000017 (ops 79-83)
I20260812 06:18:12.432512 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000018 (ops 84-88)
I20260812 06:18:12.432547 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000019 (ops 89-92)
I20260812 06:18:12.432624 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000020 (ops 93-97)
I20260812 06:18:12.432689 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000021 (ops 98-102)
I20260812 06:18:12.432731 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000022 (ops 103-107)
I20260812 06:18:12.432767 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000023 (ops 108-112)
I20260812 06:18:12.432806 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000024 (ops 113-116)
I20260812 06:18:12.432842 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000025 (ops 117-121)
I20260812 06:18:12.432878 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000026 (ops 122-126)
I20260812 06:18:12.459533 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: LogGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:12.460053 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:12.474814 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.015s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4225733,"delete_count":0,"lbm_write_time_us":4610,"lbm_writes_lt_1ms":106,"reinsert_count":0,"update_count":515}
I20260812 06:18:12.475274 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:12.485463 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3979583,"delete_count":0,"lbm_write_time_us":3843,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:12.486080 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747): 462 bytes on disk
I20260812 06:18:12.486585 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747) 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:18:12.487192 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:12.691912 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.205s	user 0.134s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2934,"lbm_read_time_us":12562,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33957,"lbm_writes_lt_1ms":643,"mutex_wait_us":2057,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29952,"thread_start_us":128,"threads_started":1,"update_count":3000}
I20260812 06:18:12.692883 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=14.095187
I20260812 06:18:12.747044 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.054s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20521,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.747682 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:12.763410 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.764019 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:12.952173 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.188s	user 0.150s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1817,"lbm_read_time_us":14061,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31599,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:12.954487 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=11.118625
I20260812 06:18:12.999907 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.045s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15328,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:13.000633 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:13.017782 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.017s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3755,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.018283 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:13.028695 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.029138 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:13.210539 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.181s	user 0.113s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":149,"lbm_read_time_us":10862,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30363,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:18:13.211266 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=14.095187
I20260812 06:18:13.276700 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.065s	user 0.021s	sys 0.041s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24391,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:13.277324 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:13.288187 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4178,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.288661 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:13.477840 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.189s	user 0.122s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":272,"lbm_read_time_us":12958,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29423,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":88064,"update_count":2500}
I20260812 06:18:13.478574 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=14.095187
I20260812 06:18:13.543731 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.065s	user 0.021s	sys 0.035s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21552,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:13.544380 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:13.560989 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.016s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6338,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.561724 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:13.734937 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.173s	user 0.115s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":393,"lbm_read_time_us":12338,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28704,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:18:13.735714 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=11.118625
I20260812 06:18:13.774238 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.038s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16377,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:13.774868 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:13.789464 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5051,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.790023 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:13.915084 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.125s	user 0.090s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":7256,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23917,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:13.915766 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=10.126437
I20260812 06:18:13.955852 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17472,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.956452 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:13.972970 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.973469 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:14.003274 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushMRSOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1310,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2022,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:14.004002 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling LogGCOp(e9b4fd55129f4d01a298f38d7b319747): free 121006640 bytes of WAL
I20260812 06:18:14.004283 13056 log_reader.cc:385] T e9b4fd55129f4d01a298f38d7b319747: removed 12 log segments from log reader
I20260812 06:18:14.004347 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000027 (ops 127-131)
I20260812 06:18:14.004390 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000028 (ops 132-136)
I20260812 06:18:14.004426 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000029 (ops 137-141)
I20260812 06:18:14.004456 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000030 (ops 142-146)
I20260812 06:18:14.004494 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000031 (ops 147-151)
I20260812 06:18:14.004520 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000032 (ops 152-156)
I20260812 06:18:14.004544 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000033 (ops 157-160)
I20260812 06:18:14.004576 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000034 (ops 161-165)
I20260812 06:18:14.004609 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000035 (ops 166-170)
I20260812 06:18:14.004649 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000036 (ops 171-175)
I20260812 06:18:14.004688 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000037 (ops 176-180)
I20260812 06:18:14.004714 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000038 (ops 181-185)
I20260812 06:18:14.035687 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: LogGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.031s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:18:14.036095 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=3.181125
I20260812 06:18:14.049028 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5312,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:14.049502 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling LogGCOp(e9b4fd55129f4d01a298f38d7b319747): free 12018004 bytes of WAL
I20260812 06:18:14.049785 13056 log_reader.cc:385] T e9b4fd55129f4d01a298f38d7b319747: removed 1 log segments from log reader
I20260812 06:18:14.049888 13056 log.cc:1079] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/e9b4fd55129f4d01a298f38d7b319747/wal-000000039 (ops 186-190)
I20260812 06:18:14.052410 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: LogGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:14.052739 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:14.066879 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5108,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:14.067466 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:14.247809 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.180s	user 0.115s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":190,"lbm_read_time_us":12742,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36512,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":26624,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:14.248381 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747): 473 bytes on disk
I20260812 06:18:14.248857 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: UndoDeltaBlockGCOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:14.249500 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=14.095187
I20260812 06:18:14.309149 12938 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.015s	user 1.841s	sys 0.201s
I20260812 06:18:14.313199 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.064s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":28414,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.313643 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747): perf score=2.188937
I20260812 06:18:14.329618 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: FlushDeltaMemStoresOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":500}
I20260812 06:18:14.330260 13131 maintenance_manager.cc:419] P d3ac0eedbe074e778a5d8eddcf8d2834: Scheduling MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747): perf score=1.000000
I20260812 06:18:14.367189 12938 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.057s	user 0.002s	sys 0.000s
I20260812 06:18:14.367887 12938 tablet_server.cc:179] TabletServer@127.12.162.129:0 shutting down...
I20260812 06:18:14.447085 13056 maintenance_manager.cc:643] P d3ac0eedbe074e778a5d8eddcf8d2834: MajorDeltaCompactionOp(e9b4fd55129f4d01a298f38d7b319747) complete. Timing: real 0.117s	user 0.100s	sys 0.016s Metrics: {"cfile_cache_hit":376,"cfile_cache_hit_bytes":15384491,"cfile_cache_miss":156,"cfile_cache_miss_bytes":9390196,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":357,"lbm_read_time_us":4192,"lbm_reads_lt_1ms":188,"lbm_write_time_us":24831,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":82560,"update_count":2500}
I20260812 06:18:14.447990 12938 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:14.448442 12938 tablet_replica.cc:333] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834: stopping tablet replica
I20260812 06:18:14.448700 12938 raft_consensus.cc:2243] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.448946 12938 raft_consensus.cc:2272] T e9b4fd55129f4d01a298f38d7b319747 P d3ac0eedbe074e778a5d8eddcf8d2834 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.454406 12938 tablet_server.cc:196] TabletServer@127.12.162.129:0 shutdown complete.
I20260812 06:18:14.494316 12938 master.cc:562] Master@127.12.162.190:46335 shutting down...
I20260812 06:18:14.498835 12938 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.499049 12938 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.499154 12938 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8523bc00f9a4459abdd30528ab0286be: stopping tablet replica
I20260812 06:18:14.511730 12938 master.cc:584] Master@127.12.162.190:46335 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5612 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:14.601075 12938 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.162.190:33435
I20260812 06:18:14.601504 12938 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.604079 13168 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:14.604130 13165 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.604267 12938 server_base.cc:1061] running on GCE node
W20260812 06:18:14.604411 13166 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.604772 12938 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.604853 12938 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:14.604882 12938 hybrid_clock.cc:648] HybridClock initialized: now 1786515494604881 us; error 0 us; skew 500 ppm
I20260812 06:18:14.605908 12938 webserver.cc:533] Webserver started at http://127.12.162.190:33541/ using document root <none> and password file <none>
I20260812 06:18:14.606092 12938 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.606218 12938 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.606315 12938 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.606761 12938 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/master-0-root/instance:
uuid: "27b7566f129f4a578461d8aed75ef5b2"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-69rg"
I20260812 06:18:14.608424 12938 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:14.609740 13174 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.610158 12938 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:14.610231 12938 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/master-0-root
uuid: "27b7566f129f4a578461d8aed75ef5b2"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-69rg"
I20260812 06:18:14.610296 12938 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:14.631105 12938 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.631515 12938 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.635627 12938 rpc_server.cc:307] RPC server started. Bound to: 127.12.162.190:33435
I20260812 06:18:14.638510 13237 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.640520 13236 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.162.190:33435 every 8 connection(s)
I20260812 06:18:14.649961 13237 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2: Bootstrap starting.
I20260812 06:18:14.650951 13237 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.652148 13237 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2: No bootstrap required, opened a new log
I20260812 06:18:14.652611 13237 raft_consensus.cc:359] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27b7566f129f4a578461d8aed75ef5b2" member_type: VOTER }
I20260812 06:18:14.652704 13237 raft_consensus.cc:385] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.652777 13237 raft_consensus.cc:740] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 27b7566f129f4a578461d8aed75ef5b2, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.652971 13237 consensus_queue.cc:260] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [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: "27b7566f129f4a578461d8aed75ef5b2" member_type: VOTER }
I20260812 06:18:14.653053 13237 raft_consensus.cc:399] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.653123 13237 raft_consensus.cc:493] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.653209 13237 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.654078 13237 raft_consensus.cc:515] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27b7566f129f4a578461d8aed75ef5b2" member_type: VOTER }
I20260812 06:18:14.654243 13237 leader_election.cc:304] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [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: 27b7566f129f4a578461d8aed75ef5b2; no voters: 
I20260812 06:18:14.654474 13237 leader_election.cc:290] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.654637 13241 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.654861 13241 raft_consensus.cc:697] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 1 LEADER]: Becoming Leader. State: Replica: 27b7566f129f4a578461d8aed75ef5b2, State: Running, Role: LEADER
I20260812 06:18:14.654983 13237 sys_catalog.cc:565] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:14.655019 13241 consensus_queue.cc:237] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [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: "27b7566f129f4a578461d8aed75ef5b2" member_type: VOTER }
I20260812 06:18:14.655495 13242 sys_catalog.cc:455] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "27b7566f129f4a578461d8aed75ef5b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27b7566f129f4a578461d8aed75ef5b2" member_type: VOTER } }
I20260812 06:18:14.655608 13242 sys_catalog.cc:458] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.655511 13243 sys_catalog.cc:455] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 27b7566f129f4a578461d8aed75ef5b2. Latest consensus state: current_term: 1 leader_uuid: "27b7566f129f4a578461d8aed75ef5b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27b7566f129f4a578461d8aed75ef5b2" member_type: VOTER } }
I20260812 06:18:14.655859 13243 sys_catalog.cc:458] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.656394 13246 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:14.657091 13246 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:14.657275 12938 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:14.659067 13246 catalog_manager.cc:1383] Generated new cluster ID: 99e71ad835a64f07be7444fa5deff705
I20260812 06:18:14.659133 13246 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:14.691530 13246 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:14.692207 13246 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:14.698141 13246 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2: Generated new TSK 0
I20260812 06:18:14.698410 13246 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:14.722111 12938 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.728322 13264 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.728396 12938 server_base.cc:1061] running on GCE node
W20260812 06:18:14.728367 13262 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:14.728336 13261 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.728941 12938 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.728991 12938 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:14.729008 12938 hybrid_clock.cc:648] HybridClock initialized: now 1786515494729008 us; error 0 us; skew 500 ppm
I20260812 06:18:14.730098 12938 webserver.cc:533] Webserver started at http://127.12.162.129:44471/ using document root <none> and password file <none>
I20260812 06:18:14.730299 12938 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.730370 12938 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.730464 12938 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.730891 12938 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/instance:
uuid: "b0ebe2079cad4318b791b461bfdaf79d"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-69rg"
I20260812 06:18:14.732590 12938 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:14.733932 13270 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.734274 12938 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:14.734392 12938 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root
uuid: "b0ebe2079cad4318b791b461bfdaf79d"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-69rg"
I20260812 06:18:14.734496 12938 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:14.749140 12938 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.749588 12938 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.750011 12938 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:14.750522 12938 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:14.750587 12938 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.750640 12938 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:14.750694 12938 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.756140 12938 rpc_server.cc:307] RPC server started. Bound to: 127.12.162.129:45815
I20260812 06:18:14.756223 13345 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.162.129:45815 every 8 connection(s)
I20260812 06:18:14.765542 13346 heartbeater.cc:344] Connected to a master server at 127.12.162.190:33435
I20260812 06:18:14.765724 13346 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:14.766067 13346 heartbeater.cc:507] Master 127.12.162.190:33435 requested a full tablet report, sending...
I20260812 06:18:14.766942 13196 ts_manager.cc:194] Registered new tserver with Master: b0ebe2079cad4318b791b461bfdaf79d (127.12.162.129:45815)
I20260812 06:18:14.766997 12938 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01027495s
I20260812 06:18:14.767859 13196 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34410
I20260812 06:18:14.774995 13196 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34422:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:14.784107 13304 tablet_service.cc:1511] Processing CreateTablet for tablet b06f2532a5c04b938716b64292544821 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6846c46c70674f42a218e6e05ead2886]), partition=
I20260812 06:18:14.784403 13304 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b06f2532a5c04b938716b64292544821. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.786551 13360 tablet_bootstrap.cc:492] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Bootstrap starting.
I20260812 06:18:14.787467 13360 tablet_bootstrap.cc:654] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.788528 13360 tablet_bootstrap.cc:492] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: No bootstrap required, opened a new log
I20260812 06:18:14.788633 13360 ts_tablet_manager.cc:1403] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:14.789144 13360 raft_consensus.cc:359] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0ebe2079cad4318b791b461bfdaf79d" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 45815 } }
I20260812 06:18:14.789283 13360 raft_consensus.cc:385] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.789330 13360 raft_consensus.cc:740] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b0ebe2079cad4318b791b461bfdaf79d, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.789484 13360 consensus_queue.cc:260] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [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: "b0ebe2079cad4318b791b461bfdaf79d" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 45815 } }
I20260812 06:18:14.789587 13360 raft_consensus.cc:399] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.789641 13360 raft_consensus.cc:493] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.789687 13360 raft_consensus.cc:3060] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.790486 13360 raft_consensus.cc:515] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0ebe2079cad4318b791b461bfdaf79d" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 45815 } }
I20260812 06:18:14.790607 13360 leader_election.cc:304] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [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: b0ebe2079cad4318b791b461bfdaf79d; no voters: 
I20260812 06:18:14.790764 13360 leader_election.cc:290] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.790969 13362 raft_consensus.cc:2804] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.791090 13362 raft_consensus.cc:697] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 1 LEADER]: Becoming Leader. State: Replica: b0ebe2079cad4318b791b461bfdaf79d, State: Running, Role: LEADER
I20260812 06:18:14.791081 13346 heartbeater.cc:499] Master 127.12.162.190:33435 was elected leader, sending a full tablet report...
I20260812 06:18:14.791083 13360 ts_tablet_manager.cc:1434] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:14.791296 13362 consensus_queue.cc:237] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [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: "b0ebe2079cad4318b791b461bfdaf79d" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 45815 } }
I20260812 06:18:14.792680 13196 catalog_manager.cc:5719] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d reported cstate change: term changed from 0 to 1, leader changed from <none> to b0ebe2079cad4318b791b461bfdaf79d (127.12.162.129). New cstate: current_term: 1 leader_uuid: "b0ebe2079cad4318b791b461bfdaf79d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0ebe2079cad4318b791b461bfdaf79d" member_type: VOTER last_known_addr { host: "127.12.162.129" port: 45815 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:14.853042 12938 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.012s	sys 0.010s
I20260812 06:18:15.007290 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushMRSOp(b06f2532a5c04b938716b64292544821): perf score=19.054940
I20260812 06:18:15.161629 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushMRSOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.154s	user 0.106s	sys 0.044s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1051,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40161,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":6016,"update_count":1550}
I20260812 06:18:15.162418 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling LogGCOp(b06f2532a5c04b938716b64292544821): free 20743880 bytes of WAL
I20260812 06:18:15.162758 13276 log_reader.cc:385] T b06f2532a5c04b938716b64292544821: removed 2 log segments from log reader
I20260812 06:18:15.162829 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000001 (ops 1-6)
I20260812 06:18:15.162863 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000002 (ops 7-11)
I20260812 06:18:15.167636 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: LogGCOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:15.167963 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821): 16411396 bytes on disk
I20260812 06:18:15.168383 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:15.168850 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:15.189785 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.021s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.190392 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:15.200065 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3672,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.200619 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:15.362735 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.162s	user 0.116s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":833,"lbm_read_time_us":12970,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28610,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":338,"threads_started":5,"update_count":2500}
I20260812 06:18:15.363446 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:15.407428 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.407932 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:15.418510 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.418985 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:15.575699 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.157s	user 0.109s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":11654,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27962,"lbm_writes_lt_1ms":543,"mutex_wait_us":96,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30336,"update_count":2500}
I20260812 06:18:15.576572 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=12.110812
I20260812 06:18:15.617216 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.040s	user 0.032s	sys 0.004s Metrics: {"bytes_written":14030499,"delete_count":0,"lbm_write_time_us":17408,"lbm_writes_lt_1ms":345,"reinsert_count":0,"update_count":1710}
I20260812 06:18:15.617810 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=1.196750
I20260812 06:18:15.638518 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.020s	user 0.001s	sys 0.009s Metrics: {"bytes_written":2789860,"delete_count":0,"lbm_write_time_us":3750,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:18:15.639025 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:15.648564 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3521,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.648998 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:15.834157 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.185s	user 0.105s	sys 0.077s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774764,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":338,"lbm_read_time_us":13937,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30206,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24192,"update_count":2500}
I20260812 06:18:15.834901 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:15.888747 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.054s	user 0.011s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22987,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.889189 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:15.900555 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.901140 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:16.066848 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.166s	user 0.114s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":586,"lbm_read_time_us":11882,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27866,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:18:16.067555 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:16.130873 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.063s	user 0.037s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20543,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.131448 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:16.142527 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.142959 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:16.318724 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.176s	user 0.103s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":12040,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29107,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:16.319486 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=11.118625
I20260812 06:18:16.363754 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.044s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19015,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:16.364254 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:16.386139 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.022s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5214,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:16.386680 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:16.401278 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5854,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.401702 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushMRSOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:16.440660 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushMRSOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.039s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1346,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1369,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:16.441304 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling LogGCOp(b06f2532a5c04b938716b64292544821): free 124710247 bytes of WAL
I20260812 06:18:16.441576 13276 log_reader.cc:385] T b06f2532a5c04b938716b64292544821: removed 12 log segments from log reader
I20260812 06:18:16.441637 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000003 (ops 12-16)
I20260812 06:18:16.441677 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000004 (ops 17-21)
I20260812 06:18:16.441705 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000005 (ops 22-26)
I20260812 06:18:16.441731 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000006 (ops 27-31)
I20260812 06:18:16.441761 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000007 (ops 32-36)
I20260812 06:18:16.441800 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000008 (ops 37-41)
I20260812 06:18:16.441856 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000009 (ops 42-46)
I20260812 06:18:16.441883 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000010 (ops 47-51)
I20260812 06:18:16.441913 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000011 (ops 52-56)
I20260812 06:18:16.441939 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000012 (ops 57-61)
I20260812 06:18:16.441968 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000013 (ops 62-66)
I20260812 06:18:16.442003 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000014 (ops 67-71)
I20260812 06:18:16.471370 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: LogGCOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:16.471951 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821): 472 bytes on disk
I20260812 06:18:16.472426 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.472966 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:16.497148 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.024s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.497587 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:16.511886 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.512349 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:16.759384 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.247s	user 0.168s	sys 0.062s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979861,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":820,"lbm_read_time_us":15591,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40598,"lbm_writes_lt_1ms":743,"mutex_wait_us":271,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:18:16.760085 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=18.063937
I20260812 06:18:16.825093 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.065s	user 0.028s	sys 0.027s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26335,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:16.825590 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:16.837173 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.837785 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:17.036648 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.199s	user 0.139s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":812,"lbm_read_time_us":13991,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34041,"lbm_writes_lt_1ms":643,"mutex_wait_us":370,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:18:17.037303 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=15.087375
I20260812 06:18:17.086720 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.049s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16820139,"delete_count":0,"lbm_write_time_us":21072,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:17.087484 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:17.098539 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":500}
I20260812 06:18:17.098994 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:17.108503 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3747,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:17.108974 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:17.279946 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.171s	user 0.134s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2207,"lbm_read_time_us":14777,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32210,"lbm_writes_lt_1ms":643,"mutex_wait_us":664,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":3000}
I20260812 06:18:17.280686 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:17.334844 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.054s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23575,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.335419 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=3.181125
I20260812 06:18:17.358572 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.023s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7021,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:17.359035 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:17.368510 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3515,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:17.368957 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:17.533618 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.164s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":968,"lbm_read_time_us":12614,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33445,"lbm_writes_lt_1ms":643,"mutex_wait_us":273,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:17.534204 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:17.594549 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.060s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":29501,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.595105 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:17.606249 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.606738 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:17.767242 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.160s	user 0.110s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":424,"lbm_read_time_us":11286,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29732,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":42240,"update_count":2500}
I20260812 06:18:17.767869 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=12.110812
I20260812 06:18:17.806782 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.039s	user 0.026s	sys 0.011s Metrics: {"bytes_written":13661282,"delete_count":0,"lbm_write_time_us":16485,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1665}
I20260812 06:18:17.807286 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=1.196750
I20260812 06:18:17.821249 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.014s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3852,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:17.821792 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushMRSOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:17.879917 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushMRSOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.058s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1489,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1586,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:17.880656 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling LogGCOp(b06f2532a5c04b938716b64292544821): free 120100381 bytes of WAL
I20260812 06:18:17.880892 13276 log_reader.cc:385] T b06f2532a5c04b938716b64292544821: removed 12 log segments from log reader
I20260812 06:18:17.880954 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000015 (ops 72-76)
I20260812 06:18:17.881006 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000016 (ops 77-81)
I20260812 06:18:17.881067 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000017 (ops 82-86)
I20260812 06:18:17.881108 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000018 (ops 87-90)
I20260812 06:18:17.881145 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000019 (ops 91-95)
I20260812 06:18:17.881179 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000020 (ops 96-100)
I20260812 06:18:17.881215 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000021 (ops 101-105)
I20260812 06:18:17.881253 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000022 (ops 106-110)
I20260812 06:18:17.881290 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000023 (ops 111-114)
I20260812 06:18:17.881326 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000024 (ops 115-119)
I20260812 06:18:17.881362 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000025 (ops 120-124)
I20260812 06:18:17.881399 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000026 (ops 125-128)
I20260812 06:18:17.908787 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: LogGCOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:17.909265 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821): 473 bytes on disk
I20260812 06:18:17.910061 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:17.910557 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=6.157687
I20260812 06:18:17.930234 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.020s	user 0.012s	sys 0.007s Metrics: {"bytes_written":8246106,"delete_count":0,"lbm_write_time_us":8452,"lbm_writes_lt_1ms":204,"reinsert_count":0,"update_count":1005}
I20260812 06:18:17.930742 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:17.943506 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4758,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:17.944049 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:18.167332 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.223s	user 0.140s	sys 0.078s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979718,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":156,"lbm_read_time_us":16198,"lbm_reads_lt_1ms":766,"lbm_write_time_us":38651,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:18:18.168080 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=18.063937
I20260812 06:18:18.219946 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.051s	user 0.021s	sys 0.028s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23057,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:18.221748 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:18.234243 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.234799 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:18.397362 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.162s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":549,"lbm_read_time_us":11881,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35569,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":3000}
I20260812 06:18:18.398116 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:18.447712 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.049s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23853,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.448297 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:18.473222 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.025s	user 0.012s	sys 0.000s 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:18:18.473685 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:18.484040 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.484470 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:18.657572 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.173s	user 0.132s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":196,"lbm_read_time_us":11667,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38286,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":3000}
I20260812 06:18:18.658308 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:18.712610 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.054s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19580,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.713186 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:18.728626 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.729517 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:18.880450 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.151s	user 0.109s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":919,"lbm_read_time_us":9912,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29256,"lbm_writes_lt_1ms":543,"mutex_wait_us":547,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2500}
I20260812 06:18:18.881073 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=11.118625
I20260812 06:18:18.927343 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.046s	user 0.015s	sys 0.028s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20762,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.927896 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:18.949542 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.021s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.950059 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:18.959815 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3736,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.960259 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:19.162225 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.202s	user 0.113s	sys 0.081s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1570,"lbm_read_time_us":13685,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31268,"lbm_writes_lt_1ms":543,"mutex_wait_us":357,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:18:19.163194 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=14.095187
I20260812 06:18:19.222447 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.059s	user 0.042s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26645,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.222967 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushMRSOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:19.261062 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushMRSOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.038s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":347,"dirs.run_wall_time_us":1428,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1587,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:19.261951 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821): 462 bytes on disk
I20260812 06:18:19.262388 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: UndoDeltaBlockGCOp(b06f2532a5c04b938716b64292544821) 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:18:19.262893 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=3.181125
I20260812 06:18:19.282867 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.020s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6965,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:19.283414 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling LogGCOp(b06f2532a5c04b938716b64292544821): free 121006701 bytes of WAL
I20260812 06:18:19.283670 13276 log_reader.cc:385] T b06f2532a5c04b938716b64292544821: removed 12 log segments from log reader
I20260812 06:18:19.283763 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000027 (ops 129-133)
I20260812 06:18:19.283839 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000028 (ops 134-138)
I20260812 06:18:19.283879 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000029 (ops 139-143)
I20260812 06:18:19.283919 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000030 (ops 144-148)
I20260812 06:18:19.283958 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000031 (ops 149-153)
I20260812 06:18:19.283996 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000032 (ops 154-158)
I20260812 06:18:19.284036 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000033 (ops 159-163)
I20260812 06:18:19.284075 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000034 (ops 164-168)
I20260812 06:18:19.284113 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000035 (ops 169-172)
I20260812 06:18:19.284152 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000036 (ops 173-177)
I20260812 06:18:19.284198 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000037 (ops 178-182)
I20260812 06:18:19.284235 13276 log.cc:1079] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: Deleting log segment in path: /tmp/dist-test-taskWUreDI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488978181-12938-0/minicluster-data/ts-0-root/wals/b06f2532a5c04b938716b64292544821/wal-000000038 (ops 183-187)
I20260812 06:18:19.311247 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: LogGCOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:19.311868 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:19.323983 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.012s	user 0.003s	sys 0.006s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:19.324414 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=2.188937
I20260812 06:18:19.335001 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4011,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:19.335491 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821): perf score=1.000000
I20260812 06:18:19.566402 12938 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.713s	user 1.782s	sys 0.120s
I20260812 06:18:19.568847 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: MajorDeltaCompactionOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.233s	user 0.143s	sys 0.082s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979744,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":507,"lbm_read_time_us":15651,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41155,"lbm_writes_lt_1ms":743,"mutex_wait_us":76,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:18:19.569564 13347 maintenance_manager.cc:419] P b0ebe2079cad4318b791b461bfdaf79d: Scheduling FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821): perf score=18.063937
I20260812 06:18:19.601154 12938 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.034s	user 0.001s	sys 0.001s
I20260812 06:18:19.601840 12938 tablet_server.cc:179] TabletServer@127.12.162.129:0 shutting down...
I20260812 06:18:19.631918 13276 maintenance_manager.cc:643] P b0ebe2079cad4318b791b461bfdaf79d: FlushDeltaMemStoresOp(b06f2532a5c04b938716b64292544821) complete. Timing: real 0.062s	user 0.041s	sys 0.019s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28163,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:19.632606 12938 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:19.632843 12938 tablet_replica.cc:333] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d: stopping tablet replica
I20260812 06:18:19.632979 12938 raft_consensus.cc:2243] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.633172 12938 raft_consensus.cc:2272] T b06f2532a5c04b938716b64292544821 P b0ebe2079cad4318b791b461bfdaf79d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.636742 12938 tablet_server.cc:196] TabletServer@127.12.162.129:0 shutdown complete.
I20260812 06:18:19.639523 12938 master.cc:562] Master@127.12.162.190:33435 shutting down...
I20260812 06:18:19.642617 12938 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.642764 12938 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.642813 12938 tablet_replica.cc:333] T 00000000000000000000000000000000 P 27b7566f129f4a578461d8aed75ef5b2: stopping tablet replica
I20260812 06:18:19.655191 12938 master.cc:584] Master@127.12.162.190:33435 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5142 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10756 ms total)

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