[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:35.483632  1867 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.210.254:45969
I20260812 06:17:35.484593  1867 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:35.485147  1867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:35.491452  1879 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:17:35.491494  1881 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:35.491648  1867 server_base.cc:1061] running on GCE node
W20260812 06:17:35.491703  1878 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:35.492183  1867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:35.492272  1867 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:35.492300  1867 hybrid_clock.cc:648] HybridClock initialized: now 1786515455492299 us; error 0 us; skew 500 ppm
I20260812 06:17:35.494032  1867 webserver.cc:533] Webserver started at http://127.1.210.254:42321/ using document root <none> and password file <none>
I20260812 06:17:35.494546  1867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:35.494604  1867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:35.494793  1867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:35.496378  1867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/master-0-root/instance:
uuid: "d19c1f2091c5445a9cb576c7edcb0173"
format_stamp: "Formatted at 2026-08-12 06:17:35 on dist-test-slave-21b9"
I20260812 06:17:35.499814  1867 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:35.501915  1887 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:35.502943  1867 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:35.503046  1867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/master-0-root
uuid: "d19c1f2091c5445a9cb576c7edcb0173"
format_stamp: "Formatted at 2026-08-12 06:17:35 on dist-test-slave-21b9"
I20260812 06:17:35.503144  1867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:35.547528  1867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:35.548200  1867 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:35.548360  1867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:35.555795  1867 rpc_server.cc:307] RPC server started. Bound to: 127.1.210.254:45969
I20260812 06:17:35.555801  1994 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.210.254:45969 every 8 connection(s)
I20260812 06:17:35.557955  1995 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:35.563222  1995 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173: Bootstrap starting.
I20260812 06:17:35.565472  1995 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:35.566313  1995 log.cc:826] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:35.568001  1995 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173: No bootstrap required, opened a new log
I20260812 06:17:35.570626  1995 raft_consensus.cc:359] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d19c1f2091c5445a9cb576c7edcb0173" member_type: VOTER }
I20260812 06:17:35.570785  1995 raft_consensus.cc:385] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:35.570824  1995 raft_consensus.cc:740] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d19c1f2091c5445a9cb576c7edcb0173, State: Initialized, Role: FOLLOWER
I20260812 06:17:35.571434  1995 consensus_queue.cc:260] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [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: "d19c1f2091c5445a9cb576c7edcb0173" member_type: VOTER }
I20260812 06:17:35.571578  1995 raft_consensus.cc:399] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:35.571624  1995 raft_consensus.cc:493] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:35.571710  1995 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:35.572425  1995 raft_consensus.cc:515] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d19c1f2091c5445a9cb576c7edcb0173" member_type: VOTER }
I20260812 06:17:35.572800  1995 leader_election.cc:304] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [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: d19c1f2091c5445a9cb576c7edcb0173; no voters: 
I20260812 06:17:35.573062  1995 leader_election.cc:290] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:35.573192  2011 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:35.573436  2011 raft_consensus.cc:697] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 1 LEADER]: Becoming Leader. State: Replica: d19c1f2091c5445a9cb576c7edcb0173, State: Running, Role: LEADER
I20260812 06:17:35.573781  2011 consensus_queue.cc:237] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [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: "d19c1f2091c5445a9cb576c7edcb0173" member_type: VOTER }
I20260812 06:17:35.573987  1995 sys_catalog.cc:565] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:35.575640  2012 sys_catalog.cc:455] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d19c1f2091c5445a9cb576c7edcb0173" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d19c1f2091c5445a9cb576c7edcb0173" member_type: VOTER } }
I20260812 06:17:35.575686  2013 sys_catalog.cc:455] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d19c1f2091c5445a9cb576c7edcb0173. Latest consensus state: current_term: 1 leader_uuid: "d19c1f2091c5445a9cb576c7edcb0173" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d19c1f2091c5445a9cb576c7edcb0173" member_type: VOTER } }
I20260812 06:17:35.575773  2013 sys_catalog.cc:458] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:35.575773  2012 sys_catalog.cc:458] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:35.576161  2022 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:35.578621  2022 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:35.578896  1867 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:35.583598  2022 catalog_manager.cc:1383] Generated new cluster ID: 1533fdf039654ba5a85eabf613435ae5
I20260812 06:17:35.583724  2022 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:35.601938  2022 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:35.603199  2022 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:35.616675  2022 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173: Generated new TSK 0
I20260812 06:17:35.617491  2022 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:35.643775  1867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:35.646523  2052 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:35.646693  2048 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:35.646770  1867 server_base.cc:1061] running on GCE node
W20260812 06:17:35.646792  2044 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:35.647181  1867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:35.647224  1867 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:35.647239  1867 hybrid_clock.cc:648] HybridClock initialized: now 1786515455647239 us; error 0 us; skew 500 ppm
I20260812 06:17:35.648175  1867 webserver.cc:533] Webserver started at http://127.1.210.193:36623/ using document root <none> and password file <none>
I20260812 06:17:35.648350  1867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:35.648401  1867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:35.648522  1867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:35.648891  1867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/instance:
uuid: "cd2a12a937c3483b954a40608d4e3620"
format_stamp: "Formatted at 2026-08-12 06:17:35 on dist-test-slave-21b9"
I20260812 06:17:35.650305  1867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:35.651223  2068 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:35.651476  1867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:35.651538  1867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root
uuid: "cd2a12a937c3483b954a40608d4e3620"
format_stamp: "Formatted at 2026-08-12 06:17:35 on dist-test-slave-21b9"
I20260812 06:17:35.651607  1867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:35.668087  1867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:35.668592  1867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:35.669135  1867 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:35.670004  1867 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:35.670060  1867 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:35.670110  1867 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:35.670140  1867 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:35.676656  2181 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.210.193:39705 every 8 connection(s)
I20260812 06:17:35.676625  1867 rpc_server.cc:307] RPC server started. Bound to: 127.1.210.193:39705
I20260812 06:17:35.686273  2183 heartbeater.cc:344] Connected to a master server at 127.1.210.254:45969
I20260812 06:17:35.686519  2183 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:35.686926  2183 heartbeater.cc:507] Master 127.1.210.254:45969 requested a full tablet report, sending...
I20260812 06:17:35.688282  1921 ts_manager.cc:194] Registered new tserver with Master: cd2a12a937c3483b954a40608d4e3620 (127.1.210.193:39705)
I20260812 06:17:35.688510  1867 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01116047s
I20260812 06:17:35.689760  1921 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43560
I20260812 06:17:35.697549  1921 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43572:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:35.712138  2113 tablet_service.cc:1511] Processing CreateTablet for tablet a8c207011ae34f51a342d8a6524bf6e0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=df8802904eb84e8db9341e0b8bde7bd2]), partition=
I20260812 06:17:35.712576  2113 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a8c207011ae34f51a342d8a6524bf6e0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:35.714973  2203 tablet_bootstrap.cc:492] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Bootstrap starting.
I20260812 06:17:35.715984  2203 tablet_bootstrap.cc:654] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:35.717507  2203 tablet_bootstrap.cc:492] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: No bootstrap required, opened a new log
I20260812 06:17:35.717607  2203 ts_tablet_manager.cc:1403] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:35.718070  2203 raft_consensus.cc:359] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd2a12a937c3483b954a40608d4e3620" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 39705 } }
I20260812 06:17:35.718173  2203 raft_consensus.cc:385] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:35.718204  2203 raft_consensus.cc:740] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cd2a12a937c3483b954a40608d4e3620, State: Initialized, Role: FOLLOWER
I20260812 06:17:35.718335  2203 consensus_queue.cc:260] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [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: "cd2a12a937c3483b954a40608d4e3620" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 39705 } }
I20260812 06:17:35.718420  2203 raft_consensus.cc:399] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:35.718463  2203 raft_consensus.cc:493] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:35.718509  2203 raft_consensus.cc:3060] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:35.719205  2203 raft_consensus.cc:515] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd2a12a937c3483b954a40608d4e3620" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 39705 } }
I20260812 06:17:35.719363  2203 leader_election.cc:304] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [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: cd2a12a937c3483b954a40608d4e3620; no voters: 
I20260812 06:17:35.719560  2203 leader_election.cc:290] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:35.719666  2205 raft_consensus.cc:2804] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:35.719883  2203 ts_tablet_manager.cc:1434] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:35.720145  2183 heartbeater.cc:499] Master 127.1.210.254:45969 was elected leader, sending a full tablet report...
I20260812 06:17:35.720285  2205 raft_consensus.cc:697] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 1 LEADER]: Becoming Leader. State: Replica: cd2a12a937c3483b954a40608d4e3620, State: Running, Role: LEADER
I20260812 06:17:35.720427  2205 consensus_queue.cc:237] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [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: "cd2a12a937c3483b954a40608d4e3620" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 39705 } }
I20260812 06:17:35.723173  1921 catalog_manager.cc:5719] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 reported cstate change: term changed from 0 to 1, leader changed from <none> to cd2a12a937c3483b954a40608d4e3620 (127.1.210.193). New cstate: current_term: 1 leader_uuid: "cd2a12a937c3483b954a40608d4e3620" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd2a12a937c3483b954a40608d4e3620" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 39705 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:35.794795  1867 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.020s	sys 0.012s
I20260812 06:17:35.927897  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=19.054940
I20260812 06:17:36.109158  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.181s	user 0.125s	sys 0.051s Metrics: {"bytes_written":13168992,"cfile_init":1,"compiler_manager_pool.queue_time_us":201,"delete_count":0,"dirs.queue_time_us":404,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":795,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43720,"lbm_writes_lt_1ms":778,"mutex_wait_us":1728,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":185600,"thread_start_us":104,"threads_started":1,"update_count":1605}
I20260812 06:17:36.110224  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling LogGCOp(a8c207011ae34f51a342d8a6524bf6e0): free 20743880 bytes of WAL
I20260812 06:17:36.110558  2076 log_reader.cc:385] T a8c207011ae34f51a342d8a6524bf6e0: removed 2 log segments from log reader
I20260812 06:17:36.110649  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000001 (ops 1-6)
I20260812 06:17:36.110718  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000002 (ops 7-11)
I20260812 06:17:36.115571  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: LogGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:36.116067  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:36.143023  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.027s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3979588,"delete_count":0,"lbm_write_time_us":5614,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:36.143561  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0): 16411393 bytes on disk
I20260812 06:17:36.144207  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.144634  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:36.156177  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":4168,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:17:36.156598  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:36.316146  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.159s	user 0.119s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774785,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":570,"lbm_read_time_us":12322,"lbm_reads_lt_1ms":569,"lbm_write_time_us":24535,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":276,"threads_started":5,"update_count":2500}
I20260812 06:17:36.316700  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=11.118625
I20260812 06:17:36.351871  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.035s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14530,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:36.352550  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:36.364773  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.365248  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:36.479511  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.114s	user 0.088s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":8552,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21671,"lbm_writes_lt_1ms":443,"mutex_wait_us":96,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:36.479975  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=10.126437
I20260812 06:17:36.513309  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.033s	user 0.019s	sys 0.010s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13411,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.513737  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:36.524554  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.525202  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:36.642007  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.116s	user 0.104s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":7620,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20480,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:36.643625  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=10.126437
I20260812 06:17:36.683056  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.039s	user 0.029s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13663,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.683605  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:36.693979  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.694480  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:36.809602  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.115s	user 0.091s	sys 0.024s 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":282,"lbm_read_time_us":7773,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21633,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.810089  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=10.126437
I20260812 06:17:36.853314  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.043s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12854,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.853861  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:36.864481  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.864892  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:37.001392  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.136s	user 0.088s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":979,"lbm_read_time_us":9886,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22646,"lbm_writes_lt_1ms":443,"mutex_wait_us":287,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:17:37.001904  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=10.126437
I20260812 06:17:37.033946  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.032s	user 0.024s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.034443  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:37.044276  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.044864  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:37.161675  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.117s	user 0.092s	sys 0.022s 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":578,"lbm_read_time_us":7908,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20179,"lbm_writes_lt_1ms":443,"mutex_wait_us":14,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:17:37.162158  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=10.126437
I20260812 06:17:37.202836  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.040s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14001,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.203388  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:37.213500  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.214073  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:37.245589  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1471,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1921,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:37.246479  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling LogGCOp(a8c207011ae34f51a342d8a6524bf6e0): free 112692378 bytes of WAL
I20260812 06:17:37.246755  2076 log_reader.cc:385] T a8c207011ae34f51a342d8a6524bf6e0: removed 11 log segments from log reader
I20260812 06:17:37.246809  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000003 (ops 12-16)
I20260812 06:17:37.246847  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000004 (ops 17-21)
I20260812 06:17:37.246879  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000005 (ops 22-26)
I20260812 06:17:37.246912  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000006 (ops 27-31)
I20260812 06:17:37.246942  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000007 (ops 32-36)
I20260812 06:17:37.246989  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000008 (ops 37-41)
I20260812 06:17:37.247021  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000009 (ops 42-46)
I20260812 06:17:37.247051  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000010 (ops 47-51)
I20260812 06:17:37.247080  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000011 (ops 52-56)
I20260812 06:17:37.247112  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000012 (ops 57-61)
I20260812 06:17:37.247143  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000013 (ops 62-66)
I20260812 06:17:37.267920  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: LogGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:37.268345  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0): 462 bytes on disk
I20260812 06:17:37.268779  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:37.269337  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=3.181125
I20260812 06:17:37.282986  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.013s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:37.283531  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:37.296767  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4811,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.297295  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:37.459568  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.162s	user 0.122s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":601,"lbm_read_time_us":10248,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30065,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11648,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:17:37.460101  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=14.095187
I20260812 06:17:37.505949  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.046s	user 0.011s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22287,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.506471  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:37.519254  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.519791  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:37.667120  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.147s	user 0.107s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1175,"lbm_read_time_us":8058,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27456,"lbm_writes_lt_1ms":543,"mutex_wait_us":348,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:37.667840  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=14.095187
I20260812 06:17:37.727313  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.059s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20455,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.727876  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:37.740114  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.740733  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:37.903478  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.163s	user 0.117s	sys 0.046s 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":206,"lbm_read_time_us":11856,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29024,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:37.904119  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=14.095187
I20260812 06:17:37.952869  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.049s	user 0.038s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21877,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.953457  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:37.965114  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.965626  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:38.124521  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.157s	user 0.128s	sys 0.024s 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":1033,"lbm_read_time_us":10053,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26582,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:17:38.125052  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=14.095187
I20260812 06:17:38.177949  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.053s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16097,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.178517  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:38.188714  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3806,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.189157  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:38.355448  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.166s	user 0.096s	sys 0.069s 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":289,"lbm_read_time_us":11264,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27928,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:38.355979  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=11.118625
I20260812 06:17:38.393199  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.037s	user 0.015s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14788,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:38.393836  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:38.422168  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.028s	user 0.005s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4569,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.422729  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:38.432950  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.433454  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:38.610793  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.177s	user 0.089s	sys 0.080s 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":162,"lbm_read_time_us":11281,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30505,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:38.611505  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=14.095187
I20260812 06:17:38.651790  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16669,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.652320  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:38.664440  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.664960  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:38.699648  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.034s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1334,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1498,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:38.700457  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling LogGCOp(a8c207011ae34f51a342d8a6524bf6e0): free 136728237 bytes of WAL
I20260812 06:17:38.700714  2076 log_reader.cc:385] T a8c207011ae34f51a342d8a6524bf6e0: removed 13 log segments from log reader
I20260812 06:17:38.700767  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000014 (ops 67-71)
I20260812 06:17:38.700806  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000015 (ops 72-76)
I20260812 06:17:38.700839  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000016 (ops 77-81)
I20260812 06:17:38.700872  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000017 (ops 82-86)
I20260812 06:17:38.700904  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000018 (ops 87-91)
I20260812 06:17:38.700935  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000019 (ops 92-96)
I20260812 06:17:38.700965  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000020 (ops 97-101)
I20260812 06:17:38.700995  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000021 (ops 102-106)
I20260812 06:17:38.701025  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000022 (ops 107-111)
I20260812 06:17:38.701056  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000023 (ops 112-116)
I20260812 06:17:38.701085  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000024 (ops 117-121)
I20260812 06:17:38.701115  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000025 (ops 122-126)
I20260812 06:17:38.701145  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000026 (ops 127-131)
I20260812 06:17:38.724426  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: LogGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:38.724898  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:38.743696  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.019s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.744170  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0): 492 bytes on disk
I20260812 06:17:38.744597  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.745126  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:38.755105  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.755686  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:38.977656  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.222s	user 0.151s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":535,"lbm_read_time_us":13504,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35645,"lbm_writes_lt_1ms":743,"mutex_wait_us":82,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:17:38.978173  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=18.063937
I20260812 06:17:39.074193  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.096s	user 0.020s	sys 0.023s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":69924,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:39.074810  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:39.099207  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.099668  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:39.109822  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.110247  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:39.313486  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.203s	user 0.155s	sys 0.044s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979638,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":247,"lbm_read_time_us":14693,"lbm_reads_lt_1ms":773,"lbm_write_time_us":36078,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3500}
I20260812 06:17:39.314123  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=15.087375
I20260812 06:17:39.364275  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.050s	user 0.014s	sys 0.031s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20156,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:39.364868  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:39.378064  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4825,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.378526  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:39.391834  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5090,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.392344  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:39.550715  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.158s	user 0.113s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":229,"lbm_read_time_us":11118,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29980,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":54528,"update_count":3000}
I20260812 06:17:39.551635  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=14.095187
I20260812 06:17:39.590512  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.039s	user 0.026s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16863,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:17:39.591050  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:39.602042  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.602626  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:39.755716  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.153s	user 0.114s	sys 0.039s 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":248,"lbm_read_time_us":11275,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27818,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:17:39.756284  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=11.118625
I20260812 06:17:39.799000  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.042s	user 0.014s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21031,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:39.799606  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:39.824985  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.025s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7104,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.825488  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:39.835373  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3629,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.835834  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:40.000561  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.165s	user 0.096s	sys 0.068s 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":926,"lbm_read_time_us":12042,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31067,"lbm_writes_lt_1ms":543,"mutex_wait_us":293,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:17:40.004104  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=14.095187
I20260812 06:17:40.061635  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.057s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":22620,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.062124  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:40.072027  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.072533  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:40.105846  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushMRSOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1231,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2196,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:40.106701  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling LogGCOp(a8c207011ae34f51a342d8a6524bf6e0): free 124710510 bytes of WAL
I20260812 06:17:40.106956  2076 log_reader.cc:385] T a8c207011ae34f51a342d8a6524bf6e0: removed 12 log segments from log reader
I20260812 06:17:40.107010  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000027 (ops 132-136)
I20260812 06:17:40.107048  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000028 (ops 137-141)
I20260812 06:17:40.107080  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000029 (ops 142-146)
I20260812 06:17:40.107110  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000030 (ops 147-151)
I20260812 06:17:40.107141  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000031 (ops 152-156)
I20260812 06:17:40.107172  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000032 (ops 157-161)
I20260812 06:17:40.107200  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000033 (ops 162-166)
I20260812 06:17:40.107229  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000034 (ops 167-171)
I20260812 06:17:40.107259  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000035 (ops 172-176)
I20260812 06:17:40.107340  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000036 (ops 177-181)
I20260812 06:17:40.107376  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000037 (ops 182-186)
I20260812 06:17:40.107453  2076 log.cc:1079] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/a8c207011ae34f51a342d8a6524bf6e0/wal-000000038 (ops 187-191)
I20260812 06:17:40.127427  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: LogGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:40.127873  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:40.147817  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.020s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.148296  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=2.188937
I20260812 06:17:40.158392  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.159101  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0): 473 bytes on disk
I20260812 06:17:40.159646  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: UndoDeltaBlockGCOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:17:40.160290  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:40.290165  1867 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.495s	user 1.704s	sys 0.100s
I20260812 06:17:40.350854  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.190s	user 0.125s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979755,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15074,"lbm_reads_lt_1ms":770,"lbm_write_time_us":33675,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3500}
I20260812 06:17:40.351486  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=10.126437
I20260812 06:17:40.382083  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: FlushDeltaMemStoresOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.030s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12722,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.382723  2185 maintenance_manager.cc:419] P cd2a12a937c3483b954a40608d4e3620: Scheduling MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0): perf score=1.000000
I20260812 06:17:40.383409  1867 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.005s	sys 0.000s
I20260812 06:17:40.384634  1867 tablet_server.cc:179] TabletServer@127.1.210.193:0 shutting down...
I20260812 06:17:40.470872  2076 maintenance_manager.cc:643] P cd2a12a937c3483b954a40608d4e3620: MajorDeltaCompactionOp(a8c207011ae34f51a342d8a6524bf6e0) complete. Timing: real 0.088s	user 0.056s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":351,"lbm_read_time_us":6102,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17116,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":56,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":1500}
I20260812 06:17:40.471644  1867 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:40.472113  1867 tablet_replica.cc:333] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620: stopping tablet replica
I20260812 06:17:40.472334  1867 raft_consensus.cc:2243] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:40.472549  1867 raft_consensus.cc:2272] T a8c207011ae34f51a342d8a6524bf6e0 P cd2a12a937c3483b954a40608d4e3620 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:40.488292  1867 tablet_server.cc:196] TabletServer@127.1.210.193:0 shutdown complete.
I20260812 06:17:40.505932  1867 master.cc:562] Master@127.1.210.254:45969 shutting down...
I20260812 06:17:40.509539  1867 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:40.509722  1867 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:40.509792  1867 tablet_replica.cc:333] T 00000000000000000000000000000000 P d19c1f2091c5445a9cb576c7edcb0173: stopping tablet replica
I20260812 06:17:40.521896  1867 master.cc:584] Master@127.1.210.254:45969 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5109 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:40.606230  1867 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.210.254:45231
I20260812 06:17:40.606674  1867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:40.608716  2239 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:40.608718  2233 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:40.608856  2234 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:40.608978  1867 server_base.cc:1061] running on GCE node
I20260812 06:17:40.609133  1867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:40.609167  1867 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:40.609186  1867 hybrid_clock.cc:648] HybridClock initialized: now 1786515460609186 us; error 0 us; skew 500 ppm
I20260812 06:17:40.609995  1867 webserver.cc:533] Webserver started at http://127.1.210.254:38559/ using document root <none> and password file <none>
I20260812 06:17:40.610149  1867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:40.610198  1867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:40.610275  1867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:40.610647  1867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/master-0-root/instance:
uuid: "bfed0ba1439342f18be7e4cf55665dc1"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-21b9"
I20260812 06:17:40.612155  1867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:40.613031  2252 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.613262  1867 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:40.613333  1867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/master-0-root
uuid: "bfed0ba1439342f18be7e4cf55665dc1"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-21b9"
I20260812 06:17:40.613399  1867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:40.618978  1867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.619321  1867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.623193  1867 rpc_server.cc:307] RPC server started. Bound to: 127.1.210.254:45231
I20260812 06:17:40.624504  2341 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.210.254:45231 every 8 connection(s)
I20260812 06:17:40.624878  2344 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:40.626524  2344 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1: Bootstrap starting.
I20260812 06:17:40.627205  2344 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:40.628119  2344 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1: No bootstrap required, opened a new log
I20260812 06:17:40.628490  2344 raft_consensus.cc:359] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfed0ba1439342f18be7e4cf55665dc1" member_type: VOTER }
I20260812 06:17:40.628573  2344 raft_consensus.cc:385] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:40.628602  2344 raft_consensus.cc:740] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bfed0ba1439342f18be7e4cf55665dc1, State: Initialized, Role: FOLLOWER
I20260812 06:17:40.628701  2344 consensus_queue.cc:260] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [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: "bfed0ba1439342f18be7e4cf55665dc1" member_type: VOTER }
I20260812 06:17:40.628756  2344 raft_consensus.cc:399] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:40.628782  2344 raft_consensus.cc:493] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:40.628814  2344 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:40.629439  2344 raft_consensus.cc:515] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfed0ba1439342f18be7e4cf55665dc1" member_type: VOTER }
I20260812 06:17:40.629556  2344 leader_election.cc:304] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [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: bfed0ba1439342f18be7e4cf55665dc1; no voters: 
I20260812 06:17:40.629694  2344 leader_election.cc:290] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:40.629809  2355 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:40.630018  2355 raft_consensus.cc:697] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 1 LEADER]: Becoming Leader. State: Replica: bfed0ba1439342f18be7e4cf55665dc1, State: Running, Role: LEADER
I20260812 06:17:40.630107  2344 sys_catalog.cc:565] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:40.630154  2355 consensus_queue.cc:237] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [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: "bfed0ba1439342f18be7e4cf55665dc1" member_type: VOTER }
I20260812 06:17:40.630553  2359 sys_catalog.cc:455] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bfed0ba1439342f18be7e4cf55665dc1. Latest consensus state: current_term: 1 leader_uuid: "bfed0ba1439342f18be7e4cf55665dc1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfed0ba1439342f18be7e4cf55665dc1" member_type: VOTER } }
I20260812 06:17:40.630538  2356 sys_catalog.cc:455] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bfed0ba1439342f18be7e4cf55665dc1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfed0ba1439342f18be7e4cf55665dc1" member_type: VOTER } }
I20260812 06:17:40.630646  2359 sys_catalog.cc:458] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:40.630657  2356 sys_catalog.cc:458] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:40.630940  2364 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:40.631695  2364 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:40.631929  1867 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:40.633317  2364 catalog_manager.cc:1383] Generated new cluster ID: d64ef6f709d8422ea52562efdd864ca9
I20260812 06:17:40.633375  2364 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:40.642971  2364 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:40.643563  2364 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:40.658568  2364 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1: Generated new TSK 0
I20260812 06:17:40.658758  2364 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:40.664144  1867 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:40.666081  2392 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:40.666131  2386 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:40.666177  1867 server_base.cc:1061] running on GCE node
W20260812 06:17:40.666241  2387 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:40.666469  1867 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:40.666520  1867 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:40.666540  1867 hybrid_clock.cc:648] HybridClock initialized: now 1786515460666540 us; error 0 us; skew 500 ppm
I20260812 06:17:40.667376  1867 webserver.cc:533] Webserver started at http://127.1.210.193:33485/ using document root <none> and password file <none>
I20260812 06:17:40.667537  1867 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:40.667586  1867 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:40.667658  1867 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:40.668030  1867 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/instance:
uuid: "711aaecd317747f2918cdeac08f07029"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-21b9"
I20260812 06:17:40.669425  1867 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:40.670301  2399 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.670499  1867 fs_manager.cc:730] Time spent opening block manager: real 0.000s	user 0.000s	sys 0.001s
I20260812 06:17:40.670567  1867 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root
uuid: "711aaecd317747f2918cdeac08f07029"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-21b9"
I20260812 06:17:40.670632  1867 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:40.683337  1867 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.683647  1867 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.683923  1867 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:40.684348  1867 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:40.684388  1867 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.684432  1867 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:40.684458  1867 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.688269  1867 rpc_server.cc:307] RPC server started. Bound to: 127.1.210.193:40185
I20260812 06:17:40.690027  2512 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.210.193:40185 every 8 connection(s)
I20260812 06:17:40.697666  2513 heartbeater.cc:344] Connected to a master server at 127.1.210.254:45231
I20260812 06:17:40.697758  2513 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:40.697949  2513 heartbeater.cc:507] Master 127.1.210.254:45231 requested a full tablet report, sending...
I20260812 06:17:40.698572  2280 ts_manager.cc:194] Registered new tserver with Master: 711aaecd317747f2918cdeac08f07029 (127.1.210.193:40185)
I20260812 06:17:40.698799  1867 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009889768s
I20260812 06:17:40.699312  2280 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46136
I20260812 06:17:40.705197  2280 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46152:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:40.713555  2444 tablet_service.cc:1511] Processing CreateTablet for tablet 8268ac09199445ff9c388b1e71d54e21 (DEFAULT_TABLE table=heavy-update-compaction-test [id=780c0e2758f24600a5b2a6c59cff50fc]), partition=
I20260812 06:17:40.713802  2444 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8268ac09199445ff9c388b1e71d54e21. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:40.715758  2535 tablet_bootstrap.cc:492] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Bootstrap starting.
I20260812 06:17:40.716543  2535 tablet_bootstrap.cc:654] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:40.717605  2535 tablet_bootstrap.cc:492] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: No bootstrap required, opened a new log
I20260812 06:17:40.717681  2535 ts_tablet_manager.cc:1403] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:40.718084  2535 raft_consensus.cc:359] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "711aaecd317747f2918cdeac08f07029" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 40185 } }
I20260812 06:17:40.718171  2535 raft_consensus.cc:385] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:40.718191  2535 raft_consensus.cc:740] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 711aaecd317747f2918cdeac08f07029, State: Initialized, Role: FOLLOWER
I20260812 06:17:40.718317  2535 consensus_queue.cc:260] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [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: "711aaecd317747f2918cdeac08f07029" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 40185 } }
I20260812 06:17:40.718415  2535 raft_consensus.cc:399] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:40.718464  2535 raft_consensus.cc:493] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:40.718523  2535 raft_consensus.cc:3060] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:40.719336  2535 raft_consensus.cc:515] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "711aaecd317747f2918cdeac08f07029" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 40185 } }
I20260812 06:17:40.719471  2535 leader_election.cc:304] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [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: 711aaecd317747f2918cdeac08f07029; no voters: 
I20260812 06:17:40.719663  2535 leader_election.cc:290] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:40.719756  2537 raft_consensus.cc:2804] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:40.719947  2537 raft_consensus.cc:697] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 1 LEADER]: Becoming Leader. State: Replica: 711aaecd317747f2918cdeac08f07029, State: Running, Role: LEADER
I20260812 06:17:40.719980  2513 heartbeater.cc:499] Master 127.1.210.254:45231 was elected leader, sending a full tablet report...
I20260812 06:17:40.719978  2535 ts_tablet_manager.cc:1434] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:40.720085  2537 consensus_queue.cc:237] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [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: "711aaecd317747f2918cdeac08f07029" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 40185 } }
I20260812 06:17:40.721294  2280 catalog_manager.cc:5719] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 reported cstate change: term changed from 0 to 1, leader changed from <none> to 711aaecd317747f2918cdeac08f07029 (127.1.210.193). New cstate: current_term: 1 leader_uuid: "711aaecd317747f2918cdeac08f07029" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "711aaecd317747f2918cdeac08f07029" member_type: VOTER last_known_addr { host: "127.1.210.193" port: 40185 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:40.778134  1867 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.010s	sys 0.012s
I20260812 06:17:40.940548  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushMRSOp(8268ac09199445ff9c388b1e71d54e21): perf score=23.023690
I20260812 06:17:41.104645  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushMRSOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.164s	user 0.127s	sys 0.036s Metrics: {"bytes_written":12471589,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":836,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40955,"lbm_writes_lt_1ms":861,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":8960,"update_count":1520}
I20260812 06:17:41.105527  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling LogGCOp(8268ac09199445ff9c388b1e71d54e21): free 20743880 bytes of WAL
I20260812 06:17:41.105820  2406 log_reader.cc:385] T 8268ac09199445ff9c388b1e71d54e21: removed 2 log segments from log reader
I20260812 06:17:41.105896  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000001 (ops 1-6)
I20260812 06:17:41.105940  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000002 (ops 7-11)
I20260812 06:17:41.111505  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: LogGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:41.111914  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:41.126420  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.014s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4829,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:17:41.126889  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:41.293015  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.166s	user 0.091s	sys 0.063s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":559,"lbm_read_time_us":9997,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24793,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":314,"threads_started":5,"update_count":2000}
I20260812 06:17:41.293605  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21): 20513814 bytes on disk
I20260812 06:17:41.294020  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.294427  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:41.343153  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.049s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409938,"delete_count":0,"lbm_write_time_us":19288,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.343693  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:41.359311  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.359772  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:41.533013  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.173s	user 0.113s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":10464,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27109,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:17:41.533545  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:41.578584  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.045s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17150,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.579092  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:41.590530  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.591140  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:41.751686  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.160s	user 0.113s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1003,"lbm_read_time_us":11172,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31749,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:17:41.752250  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:41.794204  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.042s	user 0.036s	sys 0.001s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16533,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.794703  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:41.805380  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.805994  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:41.953827  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.148s	user 0.135s	sys 0.005s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":8883,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27045,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:17:41.954430  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:41.998250  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.044s	user 0.033s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17047,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.998731  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:42.009241  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.009857  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:42.158427  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.148s	user 0.124s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":780,"lbm_read_time_us":10358,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29118,"lbm_writes_lt_1ms":543,"mutex_wait_us":252,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:17:42.159051  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=10.126437
I20260812 06:17:42.194281  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.035s	user 0.028s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13111,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.194798  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:42.204780  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.205304  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushMRSOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:42.234706  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushMRSOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.029s	user 0.022s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1335,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:42.235502  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling LogGCOp(8268ac09199445ff9c388b1e71d54e21): free 112239263 bytes of WAL
I20260812 06:17:42.235733  2406 log_reader.cc:385] T 8268ac09199445ff9c388b1e71d54e21: removed 11 log segments from log reader
I20260812 06:17:42.235796  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000003 (ops 12-16)
I20260812 06:17:42.235838  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000004 (ops 17-21)
I20260812 06:17:42.235868  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000005 (ops 22-26)
I20260812 06:17:42.235893  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000006 (ops 27-31)
I20260812 06:17:42.235924  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000007 (ops 32-36)
I20260812 06:17:42.235951  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000008 (ops 37-40)
I20260812 06:17:42.235978  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000009 (ops 41-45)
I20260812 06:17:42.236002  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000010 (ops 46-50)
I20260812 06:17:42.236027  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000011 (ops 51-55)
I20260812 06:17:42.236056  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000012 (ops 56-60)
I20260812 06:17:42.236088  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000013 (ops 61-65)
I20260812 06:17:42.260288  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: LogGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:42.260737  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21): 448 bytes on disk
I20260812 06:17:42.261229  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.261709  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=3.181125
I20260812 06:17:42.276638  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.015s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3885,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:42.277087  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling LogGCOp(8268ac09199445ff9c388b1e71d54e21): free 12017983 bytes of WAL
I20260812 06:17:42.277292  2406 log_reader.cc:385] T 8268ac09199445ff9c388b1e71d54e21: removed 1 log segments from log reader
I20260812 06:17:42.277351  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000014 (ops 66-70)
I20260812 06:17:42.279904  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: LogGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:42.280227  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:42.291761  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.011s	user 0.008s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.292327  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:42.452082  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.160s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":232,"lbm_read_time_us":10705,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32662,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:42.452626  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:42.499066  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.046s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18708,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.499635  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:42.515424  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.515969  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:42.666994  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.151s	user 0.109s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":9605,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28801,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:17:42.667603  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=12.110812
I20260812 06:17:42.704192  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.036s	user 0.024s	sys 0.011s Metrics: {"bytes_written":14030493,"delete_count":0,"lbm_write_time_us":16226,"lbm_writes_lt_1ms":345,"reinsert_count":0,"update_count":1710}
I20260812 06:17:42.704778  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.196750
I20260812 06:17:42.715478  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2543708,"delete_count":0,"lbm_write_time_us":3004,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:17:42.715904  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:42.870916  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.155s	user 0.119s	sys 0.024s Metrics: {"cfile_cache_miss":436,"cfile_cache_miss_bytes":20877324,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1298,"lbm_read_time_us":10627,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23410,"lbm_writes_lt_1ms":447,"mutex_wait_us":274,"peak_mem_usage":50853468,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2020}
I20260812 06:17:42.871531  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:42.919303  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.048s	user 0.026s	sys 0.013s Metrics: {"bytes_written":16245805,"delete_count":0,"lbm_write_time_us":18269,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":1980}
I20260812 06:17:42.919849  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:42.944243  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.024s	user 0.011s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.944867  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:43.131956  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.187s	user 0.114s	sys 0.064s Metrics: {"cfile_cache_miss":528,"cfile_cache_miss_bytes":24651586,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":13728,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26782,"lbm_writes_lt_1ms":539,"mutex_wait_us":2,"peak_mem_usage":61911376,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2480}
I20260812 06:17:43.132545  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:43.182211  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.049s	user 0.021s	sys 0.025s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":24704,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.182786  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:43.198504  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.199000  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:43.358279  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.159s	user 0.099s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":9682,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27722,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2500}
I20260812 06:17:43.358820  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:43.401312  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.042s	user 0.016s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16630,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.401836  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:43.413192  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.413791  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:43.558457  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.144s	user 0.113s	sys 0.026s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1056,"lbm_read_time_us":8954,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27906,"lbm_writes_lt_1ms":543,"mutex_wait_us":237,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31616,"update_count":2500}
I20260812 06:17:43.558987  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=11.118625
I20260812 06:17:43.602267  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.043s	user 0.038s	sys 0.002s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16033,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:43.602838  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:43.624456  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.021s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5760,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.624887  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:43.634008  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3280,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.634433  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushMRSOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:43.662868  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushMRSOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1324,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1309,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:43.663566  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling LogGCOp(8268ac09199445ff9c388b1e71d54e21): free 121006451 bytes of WAL
I20260812 06:17:43.663796  2406 log_reader.cc:385] T 8268ac09199445ff9c388b1e71d54e21: removed 12 log segments from log reader
I20260812 06:17:43.663862  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000015 (ops 71-75)
I20260812 06:17:43.663906  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000016 (ops 76-80)
I20260812 06:17:43.663936  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000017 (ops 81-85)
I20260812 06:17:43.663967  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000018 (ops 86-90)
I20260812 06:17:43.663998  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000019 (ops 91-94)
I20260812 06:17:43.664027  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000020 (ops 95-99)
I20260812 06:17:43.664055  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000021 (ops 100-104)
I20260812 06:17:43.664079  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000022 (ops 105-109)
I20260812 06:17:43.664108  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000023 (ops 110-114)
I20260812 06:17:43.664140  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000024 (ops 115-119)
I20260812 06:17:43.664168  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000025 (ops 120-124)
I20260812 06:17:43.664196  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000026 (ops 125-129)
I20260812 06:17:43.688351  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: LogGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:43.688810  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=3.181125
I20260812 06:17:43.704816  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.016s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:43.705267  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21): 482 bytes on disk
I20260812 06:17:43.705703  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.706200  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:43.729694  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.023s	user 0.014s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4809,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.731432  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:43.971617  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.240s	user 0.155s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020846,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1355,"lbm_read_time_us":14440,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37967,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13184,"thread_start_us":122,"threads_started":1,"update_count":3500}
I20260812 06:17:43.972610  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=18.063937
I20260812 06:17:44.067178  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.094s	user 0.037s	sys 0.015s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":62418,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:44.067821  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:44.085084  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5806,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.085605  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:44.283839  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.198s	user 0.111s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":12773,"lbm_reads_lt_1ms":664,"lbm_write_time_us":30418,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":3000}
I20260812 06:17:44.284554  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=18.063937
I20260812 06:17:44.354367  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.070s	user 0.045s	sys 0.020s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":28229,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:44.354909  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:44.365635  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.366257  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:44.553082  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.187s	user 0.115s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":13527,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32222,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":3000}
I20260812 06:17:44.553624  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:44.605053  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.051s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21274,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.605669  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:44.621102  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.621575  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:44.781481  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.160s	user 0.095s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":12443,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26625,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:44.782322  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:44.829250  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.047s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16071,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.829859  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:44.843550  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.844100  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:45.013643  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.169s	user 0.123s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":553,"lbm_read_time_us":12484,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25960,"lbm_writes_lt_1ms":543,"mutex_wait_us":250,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":36224,"update_count":2500}
I20260812 06:17:45.014171  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=14.095187
I20260812 06:17:45.066896  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.053s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18812,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.067564  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:45.077993  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.078459  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushMRSOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:45.117626  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushMRSOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.039s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":158,"dirs.run_wall_time_us":1102,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1405,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:45.118396  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling LogGCOp(8268ac09199445ff9c388b1e71d54e21): free 120553638 bytes of WAL
I20260812 06:17:45.118634  2406 log_reader.cc:385] T 8268ac09199445ff9c388b1e71d54e21: removed 12 log segments from log reader
I20260812 06:17:45.118680  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000027 (ops 130-134)
I20260812 06:17:45.118706  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000028 (ops 135-138)
I20260812 06:17:45.118738  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000029 (ops 139-143)
I20260812 06:17:45.118769  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000030 (ops 144-148)
I20260812 06:17:45.118794  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000031 (ops 149-153)
I20260812 06:17:45.118826  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000032 (ops 154-158)
I20260812 06:17:45.118860  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000033 (ops 159-162)
I20260812 06:17:45.118891  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000034 (ops 163-167)
I20260812 06:17:45.118922  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000035 (ops 168-172)
I20260812 06:17:45.118953  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000036 (ops 173-177)
I20260812 06:17:45.118984  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000037 (ops 178-182)
I20260812 06:17:45.119015  2406 log.cc:1079] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: Deleting log segment in path: /tmp/dist-test-taskGwUrRc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515455473281-1867-0/minicluster-data/ts-0-root/wals/8268ac09199445ff9c388b1e71d54e21/wal-000000038 (ops 183-187)
I20260812 06:17:45.138764  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: LogGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:17:45.139226  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21): 462 bytes on disk
I20260812 06:17:45.139788  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: UndoDeltaBlockGCOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.140448  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:45.159366  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.159799  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=2.188937
I20260812 06:17:45.169812  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.170322  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21): perf score=1.000000
I20260812 06:17:45.382957  1867 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.605s	user 1.731s	sys 0.140s
I20260812 06:17:45.385236  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: MajorDeltaCompactionOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.215s	user 0.137s	sys 0.067s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020744,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":237,"lbm_read_time_us":15770,"lbm_reads_lt_1ms":774,"lbm_write_time_us":32490,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:17:45.385790  2517 maintenance_manager.cc:419] P 711aaecd317747f2918cdeac08f07029: Scheduling FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21): perf score=18.063937
I20260812 06:17:45.425130  1867 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.042s	user 0.001s	sys 0.000s
I20260812 06:17:45.425621  1867 tablet_server.cc:179] TabletServer@127.1.210.193:0 shutting down...
I20260812 06:17:45.445727  2406 maintenance_manager.cc:643] P 711aaecd317747f2918cdeac08f07029: FlushDeltaMemStoresOp(8268ac09199445ff9c388b1e71d54e21) complete. Timing: real 0.060s	user 0.041s	sys 0.017s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":27033,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:45.446265  1867 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:45.446493  1867 tablet_replica.cc:333] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029: stopping tablet replica
I20260812 06:17:45.446636  1867 raft_consensus.cc:2243] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:45.446785  1867 raft_consensus.cc:2272] T 8268ac09199445ff9c388b1e71d54e21 P 711aaecd317747f2918cdeac08f07029 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:45.460129  1867 tablet_server.cc:196] TabletServer@127.1.210.193:0 shutdown complete.
I20260812 06:17:45.463029  1867 master.cc:562] Master@127.1.210.254:45231 shutting down...
I20260812 06:17:45.466085  1867 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:45.466234  1867 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:45.466281  1867 tablet_replica.cc:333] T 00000000000000000000000000000000 P bfed0ba1439342f18be7e4cf55665dc1: stopping tablet replica
I20260812 06:17:45.478354  1867 master.cc:584] Master@127.1.210.254:45231 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4956 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10066 ms total)

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