// Copyright (C) 2025, The Duplicati Team // https://duplicati.com, hello@duplicati.com // // Permission is hereby granted, free of charge, to any person obtaining a // copy of this software and associated documentation files (the "Software"), // to deal in the Software without restriction, including without limitation // the rights to use, copy, modify, merge, publish, distribute, sublicense, // and/or sell copies of the Software, and to permit persons to whom the // Software is furnished to do so, subject to the following conditions: // // The above copyright notice and this permission notice shall be included in // all copies or substantial portions of the Software. // // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS // OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE // AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER // LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING // FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER // DEALINGS IN THE SOFTWARE. using System; using System.Buffers; using System.Collections.Concurrent; using System.Collections.Generic; using System.Data; using System.Diagnostics; using System.Linq; using System.Threading; using System.Threading.Tasks; using CoCoL; using Duplicati.Library.Main.Database; using Microsoft.Extensions.Caching.Memory; #nullable enable namespace Duplicati.Library.Main.Operation.Restore { /// /// Process that manages the block requests and responses to/from the /// `FileProcessor` process by caching the blocks. /// internal class BlockManager { /// /// The log tag for this class. /// private static readonly string LOGTAG = Logging.Log.LogTagFromType(); /// /// Dictionary for data blocks that are being cached. Whenever a block /// is requested, it checks if it is in the cache. If it is not, it /// will request the block from the corresponding volume. The requester /// will be given a `Task` that will be completed when the block is /// available. The cache will also keep track of how many times a block /// is requested, and only remove it from the cache when all requests /// have been fulfilled. This is to ensure that the cache is not /// prematurely evicted, while keeping the memory usage low. The /// dictionary also keeps track of how many readers are accessing it, /// and will retire the volume request channel when the last reader is /// done. Once disposed, the dictionary will clean up the database /// table that was used to keep track of the block counts. /// internal class SleepableDictionary : IDisposable { /// /// Channel for submitting block requests from a volume. /// private readonly IWriteChannel m_volume_request; /// /// The dictionary holding the cached blocks. /// private readonly MemoryCache m_block_cache; /// /// Secondary counter for the number of blocks in the cache. It's faster than the MemoryCache.Count property. /// private int m_block_cache_count; /// /// The maximum number of blocks to hold in the cache. If the number of blocks exceeds this value, the cache will be compacted. It is a cached value of . /// private long m_block_cache_max; /// /// Flag indicating if the cache is currently being compacted. Used to avoid triggering multiple compactions as they are expensive. /// Multiple triggers can occur as the eviction callback is launched in a task, so the count can be above the max for a short while. /// private int m_block_cache_compacting = 0; /// /// The dictionary holding the `Task` for each block request in flight. /// private readonly ConcurrentDictionary Task)> m_waiters = []; /// /// The number of readers accessing this dictionary. Used during shutdown / cleanup. /// private int m_readers = 0; /// /// Internal stopwatch for profiling the cache eviction. /// private readonly Stopwatch? sw_cacheevict; /// /// Internal stopwatch for profiling the `CheckCounts` method. /// private readonly Stopwatch? sw_checkcounts; /// /// Internal stopwatch for profiling setting up the waiters. /// private readonly Stopwatch? sw_get_wait; /// /// Internal stopwatch for profiling writing the block request to the volume request channel. /// private readonly Stopwatch? sw_get_write; /// /// Internal stopwatch for profiling setting a block in the cache. /// private readonly Stopwatch? sw_set_set; /// /// Internal stopwatch for profiling getting a waiter to notify that the block is available. /// private readonly Stopwatch? sw_set_wake_get; /// /// Internal stopwatch for profiling for waking up the waiting request. /// private readonly Stopwatch? sw_set_wake_set; /// /// Dictionary for keeping track of how many times each block is requested. Used to determine when a block is no longer needed. /// private readonly Dictionary m_blockcount = new(); /// /// Lock for the block count dictionary. /// private readonly object m_blockcount_lock = new(); /// /// Dictionary for keeping track of how many times each volume is requested. Used to determine when a volume is no longer needed. /// private readonly Dictionary m_volumecount = new(); /// /// The options for the restore. /// private readonly Options m_options; /// /// The cache eviction options. Used for registering a callback when a block is evicted from the cache. /// private readonly MemoryCacheEntryOptions m_entry_options = new(); /// /// Flag indicating if the dictionary has been retired. Used to avoid multiple retire attempts. /// private bool m_retired = false; /// /// Initializes a new instance of the class. /// /// Channel for submitting block requests from a volume. /// Number of readers accessing this dictionary. Used during shutdown / cleanup. private SleepableDictionary(IWriteChannel volume_request, Options options, int readers) { m_options = options; m_volume_request = volume_request; var cache_options = new MemoryCacheOptions(); m_block_cache = new MemoryCache(cache_options); m_block_cache_max = options.RestoreCacheMax; m_block_cache_count = 0; m_entry_options.RegisterPostEvictionCallback((key, value, reason, state) => { if (value is DataBlock dataBlock) { dataBlock.Dispose(); } else if (value is null) { Logging.Log.WriteWarningMessage(LOGTAG, "CacheEvictCallback", null, "Evicted block {0} from cache, but the value was null", key); } else { Logging.Log.WriteWarningMessage(LOGTAG, "CacheEvictCallback", null, "Evicted block {0} from cache, but the value was of unexpected type {1}", key, value.GetType().FullName); } Interlocked.Decrement(ref m_block_cache_count); Logging.Log.WriteExplicitMessage(LOGTAG, "CacheEvictCallback", "Evicted block {0} from cache", key); if (reason is EvictionReason.Capacity) Interlocked.Exchange(ref m_block_cache_compacting, 0); }); m_readers = readers; sw_cacheevict = options.InternalProfiling ? new() : null; sw_checkcounts = options.InternalProfiling ? new() : null; sw_get_wait = options.InternalProfiling ? new() : null; sw_get_write = options.InternalProfiling ? new() : null; sw_set_set = options.InternalProfiling ? new() : null; sw_set_wake_get = options.InternalProfiling ? new() : null; sw_set_wake_set = options.InternalProfiling ? new() : null; } /// /// Asynchronously creates a new instance of the class. /// This method initializes the block and volume counts based on the data in the database. /// /// The database holding information about how many of each block this restore requires. /// CoCoL channel for submitting block requests from a volume. /// The restore options. /// The number of readers accessing this dictionary. Used during shutdown / cleanup. /// A cancellation token to cancel the operation. /// A task that when awaited returns a new instance of the class. public static async Task CreateAsync(LocalRestoreDatabase db, IWriteChannel volume_request, Options options, int readers, CancellationToken cancellationToken) { var sd = new SleepableDictionary(volume_request, options, readers); await foreach (var (block_id, volume_id) in db.GetBlocksAndVolumeIDs(options.SkipMetadata, cancellationToken).ConfigureAwait(false)) { var bc = sd.m_blockcount.TryGetValue(block_id, out var c); sd.m_blockcount[block_id] = bc ? c + 1 : 1; var vc = sd.m_volumecount.TryGetValue(volume_id, out var v); sd.m_volumecount[volume_id] = vc ? v + 1 : 1; } return sd; } /// /// Decrements the block counters for the block and volume, and checks /// if the block is still needed. If the block is no longer needed, it /// will be removed from the cache. If the volume is no longer needed, /// the VolumeDownloader will be notified. /// /// The block request to check. public async Task CheckCounts(BlockRequest blockRequest) { long error_block_id = -1; long error_volume_id = -1; var emit_evict = false; Logging.Log.WriteExplicitMessage(LOGTAG, "CheckCounts", "Trying to acquire m_blockcount_lock for block {0}", blockRequest.BlockID); lock (m_blockcount_lock) { sw_checkcounts?.Start(); var block_count = m_blockcount.TryGetValue(blockRequest.BlockID, out var c) ? c - 1 : 0; if (block_count > 0) { m_blockcount[blockRequest.BlockID] = block_count; } else if (block_count == 0) { // Evict the block from the cache and check if the volume is no longer needed. m_blockcount.Remove(blockRequest.BlockID); m_block_cache.Remove(blockRequest.BlockID); } else // block_count < 0 { error_block_id = blockRequest.BlockID; } var vol_count = m_volumecount.TryGetValue(blockRequest.VolumeID, out var vc) ? vc - 1 : 0; if (vol_count > 0) { m_volumecount[blockRequest.VolumeID] = vol_count; } else if (vol_count == 0) { m_volumecount.Remove(blockRequest.VolumeID); blockRequest.RequestType = BlockRequestType.CacheEvict; emit_evict = true; } else // vol_count < 0 { error_volume_id = blockRequest.VolumeID; } sw_checkcounts?.Stop(); } Logging.Log.WriteExplicitMessage(LOGTAG, "CheckCounts", "Released m_blockcount_lock for block {0}", blockRequest.BlockID); // Notify the `VolumeManager` that it should evict the volume. if (emit_evict) await m_volume_request.WriteAsync(blockRequest).ConfigureAwait(false); if (error_block_id != -1) { Logging.Log.WriteWarningMessage(LOGTAG, "BlockCountError", null, "Block {0} has a count below 0", blockRequest.BlockID); } if (error_volume_id != -1) { Logging.Log.WriteWarningMessage(LOGTAG, "VolumeCountError", null, "Volume {0} has a count below 0", blockRequest.VolumeID); } } /// /// Get a block from the cache. If the block is not in the cache, /// it will request the block from the volume and return a `Task` /// that will be completed when the block is available. /// /// The requested block. /// A `Task` holding the data block. public async Task Get(BlockRequest block_request) { Logging.Log.WriteExplicitMessage(LOGTAG, "BlockCacheGet", "Getting block {0} from cache", block_request.BlockID); // Check if the block is already in the cache, and return it if it is. if (m_block_cache.TryGetValue(block_request.BlockID, out DataBlock? value)) { if (value is null) throw new InvalidOperationException($"Block {block_request.BlockID} was in the cache, but the value was null"); value.Reference(); // If the block was evicted in between the TryGetValue and the Reference call, // we need to request it again. if (value.Data is not null) return value; } // If the block is not in the cache, request it from the volume. sw_get_wait?.Start(); var tcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var (_, new_tcs) = m_waiters.AddOrUpdate(block_request.BlockID, (1, tcs), (key, old) => (old.Count + 1, old.Task)); if (tcs == new_tcs) { sw_get_wait?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "BlockCacheGet", "Requesting block {0} from volume {1}", block_request.BlockID, block_request.VolumeID); // We are the first to request this block sw_get_write?.Start(); await m_volume_request.WriteAsync(block_request).ConfigureAwait(false); sw_get_write?.Stop(); // Add a timeout monitor var timeout = TimeSpan.FromMilliseconds(DeadlockTimer.MaxProcessingTime * 2); using var tcs1 = new CancellationTokenSource(); var t = await Task.WhenAny( Task.Delay(timeout, tcs1.Token), new_tcs.Task ).ConfigureAwait(false); if (t != new_tcs.Task) Logging.Log.WriteWarningMessage(LOGTAG, "BlockRequestTimeout", null, "Block request for block {0} has been in flight for over {1} milliseconds. This may be a deadlock.", block_request.BlockID, timeout.TotalMilliseconds); } else { sw_get_wait?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "BlockCacheGet", "Block {0} is already being requested, waiting for it to be available", block_request.BlockID); } return await new_tcs.Task.ConfigureAwait(false); } /// /// Set a block in the cache. If the block is already in the cache, /// it will be replaced. If the block is not in the cache, it will /// be added. If the block is no longer needed, it will be removed /// from the cache. If the block is requested while it is being /// removed, the requester will be given a `Task` that will be /// completed when the block is available. /// /// The block request related to the value. /// The byte[] buffer holding the block data. public void Set(long blockID, DataBlock value) { Logging.Log.WriteExplicitMessage(LOGTAG, "BlockCacheSet", "Setting block {0} in cache", blockID); sw_set_wake_get?.Start(); var waiters_exist = m_waiters.TryRemove(blockID, out var entry); sw_set_wake_get?.Stop(); sw_set_set?.Start(); bool fullfills = waiters_exist && entry.Count >= m_blockcount[blockID]; bool added_to_cache = !fullfills && m_block_cache_max > 0; if (added_to_cache) { m_block_cache.Set(blockID, value, m_entry_options); Interlocked.Increment(ref m_block_cache_count); } sw_set_set?.Stop(); // Notify any waiters that the block is available. sw_set_wake_set?.Start(); if (waiters_exist) { value.Reference(entry.Count); entry.Task.SetResult(value); } sw_set_wake_set?.Stop(); sw_cacheevict?.Start(); if (added_to_cache) { if (m_block_cache_count > m_block_cache_max && Interlocked.CompareExchange(ref m_block_cache_compacting, 1, 0) == 0) m_block_cache.Compact(m_options.RestoreCacheEvict); } else // This method is responsible for the disposal value.Dispose(); sw_cacheevict?.Stop(); } /// /// Retire the dictionary. This will decrement the number of readers /// accessing the dictionary, and if there are no more readers, it /// will retire the volume request channel, effectively shutting /// down the restore process network. /// public void Retire() { if (!m_retired && Interlocked.Decrement(ref m_readers) <= 0) { m_volume_request.Retire(); m_retired = true; } } /// /// Clean up the dictionary. This will remove the database table /// that was used to keep track of the block counts. /// public void Dispose() { // Verify that the tables are empty var blockcount = m_blockcount.Sum(x => x.Value); var volumecount = m_volumecount.Sum(x => x.Value); if (blockcount != 0) { var blocks = m_blockcount .Where(x => x.Value != 0) .Take(10) .Select(x => x.Key); var blockids = string.Join(", ", blocks); Logging.Log.WriteErrorMessage(LOGTAG, "BlockCountError", null, $"Block count in SleepableDictionarys block table is not zero: {blockcount}{Environment.NewLine}First 10 blocks: {blockids}"); } if (volumecount != 0) { var vols = m_volumecount .Where(x => x.Value != 0) .Take(10) .Select(x => x.Key); var volids = string.Join(", ", vols); Logging.Log.WriteErrorMessage(LOGTAG, "VolumeCountError", null, $"Volume count in SleepableDictionarys volume table is not zero: {volumecount}{Environment.NewLine}First 10 volumes: {volids}"); } if (m_block_cache.Count > 0) { Logging.Log.WriteErrorMessage(LOGTAG, "BlockCacheMismatch", null, $"Internal Block cache is not empty: {m_block_cache.Count}"); Logging.Log.WriteErrorMessage(LOGTAG, "BlockCacheMismatch", null, $"First 10 block counts in cache ({m_blockcount.Count}): {string.Join(", ", m_blockcount.Take(10).Select(x => x.Value))}"); } if (m_options.InternalProfiling) { Logging.Log.WriteProfilingMessage(LOGTAG, "InternalTimings", $"Sleepable dictionary - CheckCounts: {sw_checkcounts!.ElapsedMilliseconds}ms, Get wait: {sw_get_wait!.ElapsedMilliseconds}ms, Get write: {sw_get_write!.ElapsedMilliseconds}ms, Set set: {sw_set_set!.ElapsedMilliseconds}ms, Set wake get: {sw_set_wake_get!.ElapsedMilliseconds}ms, Set wake set: {sw_set_wake_set!.ElapsedMilliseconds}ms, Cache evict: {sw_cacheevict!.ElapsedMilliseconds}ms"); } if (!m_retired) { Logging.Log.WriteErrorMessage(LOGTAG, "NotRetired", null, "SleepableDictionary was disposed without having retired channels."); m_retired = true; m_volume_request.Retire(); } } /// /// Cancel all pending requests. This will set an exception on all /// pending requests, effectively cancelling them. /// public void CancelAll() { foreach (var (_, tcs) in m_waiters.Values) { tcs.SetException(new RetiredException("Request waiter")); } } } /// /// Run the block manager process. This will create a cache for the /// blocks, and start two tasks: one for reading blocks from the input /// channel (data blocks from the volumes) and storing them in the /// cache, and one for reading block requests from the `FileProcessor`, /// accessing the cache for the blocks, and writing the resulting /// blocks back to the `FileProcessor`. /// /// The named channels for the restore operation. /// The database holding information about how many of each block this restore requires. /// The channels for reading block requests from the `FileProcessor`. /// The channels for writing block responses back to the `FileProcessor`. /// The restore options. /// The results of the restore operation. public static Task Run(Channels channels, LocalRestoreDatabase db, IChannel[] fp_requests, IChannel>[] fp_responses, Options options, RestoreResults results) { return AutomationExtensions.RunTask( new { Input = channels.DecompressedBlock.AsRead(), Ack = channels.DecompressionAck.AsWrite(), Output = channels.VolumeRequest.AsWrite() }, async self => { // Create a cache for the blocks, using SleepableDictionary cache = await SleepableDictionary.CreateAsync(db, self.Output, options, fp_requests.Length, results.TaskControl.ProgressToken) .ConfigureAwait(false); // The volume consumer will read blocks from the input channel (data blocks from the volumes) and store them in the cache. var volume_consumer = Task.Run(async () => { Stopwatch? sw_read = options.InternalProfiling ? new() : null; Stopwatch? sw_set = options.InternalProfiling ? new() : null; Stopwatch? sw_deadlock = options.InternalProfiling ? new() : null; try { while (true) { Logging.Log.WriteExplicitMessage(LOGTAG, "VolumeConsumer", null, "Waiting for block request from volume"); sw_read?.Start(); var (block_request, data) = await self.Input.ReadAsync().ConfigureAwait(false); sw_read?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "VolumeConsumer", null, "Received data for block {0} from volume {1}", block_request.BlockID, block_request.VolumeID); sw_set?.Start(); cache.Set(block_request.BlockID, data); sw_set?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "VolumeConsumer", null, "Updating deadlock timer for block {0} from volume {1}", block_request.BlockID, block_request.VolumeID); sw_deadlock?.Start(); DeadlockTimer.MaxProcessingTime = Math.Max(DeadlockTimer.MaxProcessingTime, (int)(DateTime.Now - block_request.TimestampMilliseconds).TotalMilliseconds); sw_deadlock?.Stop(); } } catch (RetiredException) { Logging.Log.WriteVerboseMessage(LOGTAG, "RetiredProcess", null, "BlockManager Volume consumer retired"); if (options.InternalProfiling) { Logging.Log.WriteProfilingMessage(LOGTAG, "InternalTimings", $"Volume consumer - Read: {sw_read!.ElapsedMilliseconds}ms, Set: {sw_set!.ElapsedMilliseconds}ms, Deadlock timer: {sw_deadlock!.ElapsedMilliseconds}ms"); } // Cancel any remaining readers - although there shouldn't be any. cache.CancelAll(); } catch (Exception ex) { Logging.Log.WriteErrorMessage(LOGTAG, "VolumeConsumerError", ex, "Error in volume consumer"); self.Input.Retire(); // Cancel any remaining readers - although there shouldn't be any. cache.CancelAll(); cache.Retire(); } }); // The block handlers will read block requests from the `FileProcessor`, access the cache for the blocks, and write the resulting blocks to the `FileProcessor`. var block_handlers = fp_requests.Zip(fp_responses, (req, res) => Task.Run(async () => { Stopwatch? sw_req = options.InternalProfiling ? new() : null; Stopwatch? sw_resp = options.InternalProfiling ? new() : null; Stopwatch? sw_cache = options.InternalProfiling ? new() : null; Stopwatch? sw_get = options.InternalProfiling ? new() : null; try { while (true) { sw_req?.Start(); var block_request = await req.ReadAsync().ConfigureAwait(false); sw_req?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "BlockHandler", null, "Received block request: {0}", block_request.RequestType); switch (block_request.RequestType) { case BlockRequestType.Download: sw_get?.Start(); var datatask = cache.Get(block_request); sw_get?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "BlockHandler", null, "Retrieved data for block {0} and volume {1}", block_request.BlockID, block_request.VolumeID); sw_resp?.Start(); await res.WriteAsync(datatask).ConfigureAwait(false); sw_resp?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "BlockHandler", null, "Passed data for block {0} and volume {1} to FileProcessor", block_request.BlockID, block_request.VolumeID); break; case BlockRequestType.CacheEvict: sw_cache?.Start(); // Target file already had the block. await cache.CheckCounts(block_request).ConfigureAwait(false); sw_cache?.Stop(); Logging.Log.WriteExplicitMessage(LOGTAG, "BlockHandler", null, "Decremented counts for block {0} and volume {1}", block_request.BlockID, block_request.VolumeID); break; default: throw new InvalidOperationException($"Unexpected block request type: {block_request.RequestType}"); } } } catch (RetiredException) { Logging.Log.WriteVerboseMessage(LOGTAG, "RetiredProcess", null, "BlockManager Block handler retired"); if (options.InternalProfiling) { Logging.Log.WriteProfilingMessage(LOGTAG, "InternalTimings", $"Block handler - Req: {sw_req!.ElapsedMilliseconds}ms, Resp: {sw_resp!.ElapsedMilliseconds}ms, Cache: {sw_cache!.ElapsedMilliseconds}ms, Get: {sw_get!.ElapsedMilliseconds}ms"); } cache.Retire(); } catch (Exception ex) { Logging.Log.WriteErrorMessage(LOGTAG, "BlockHandlerError", ex, "Error in block handler"); req.Retire(); res.Retire(); cache.Retire(); } })).ToArray(); await Task.WhenAll([volume_consumer, .. block_handlers]).ConfigureAwait(false); }); } } }