Added internal timers to keep track of maximum processing times of the restore processes

This commit is contained in:
Carl Johnsen
2025-10-28 14:41:39 +01:00
parent f30f78f0a3
commit ccfcffcc1e
3 changed files with 53 additions and 0 deletions
@@ -22,6 +22,7 @@
using System;
using System.Buffers;
using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;
using CoCoL;
using Duplicati.Library.Utility;
@@ -41,6 +42,15 @@ namespace Duplicati.Library.Main.Operation.Restore
/// </summary>
private static readonly string LOGTAG = Logging.Log.LogTagFromType<VolumeDecompressor>();
/// <summary>
/// Id of the next decompressor. Used to give each decompressor a unique index.
/// </summary>
public static int IdCounter = -1;
/// <summary>
/// Maximum processing times for each active decompressor.
/// </summary>
public static int[] MaxProcessingTimes = [];
/// <summary>
/// Runs the volume decompressor process.
/// </summary>
@@ -64,6 +74,9 @@ namespace Duplicati.Library.Main.Operation.Restore
Stopwatch? sw_decompress_read = options.InternalProfiling ? new() : null;
Stopwatch? sw_verify = options.InternalProfiling ? new() : null;
Stopwatch sw_processing = new();
int id = Interlocked.Increment(ref IdCounter);
try
{
using var block_hasher = HashFactory.CreateHasher(options.BlockHashAlgorithm);
@@ -77,6 +90,7 @@ namespace Duplicati.Library.Main.Operation.Restore
sw_read?.Stop();
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", "Decompressing block {0} from volume {1}", block_request.BlockID, block_request.VolumeID);
sw_processing.Restart();
sw_decompress_alloc?.Start();
var data = ArrayPool<byte>.Shared.Rent(options.Blocksize);
sw_decompress_alloc?.Stop();
@@ -105,6 +119,9 @@ namespace Duplicati.Library.Main.Operation.Restore
}
sw_verify?.Stop();
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", "Verified block {0} from volume {1}", block_request.BlockID, block_request.VolumeID);
sw_processing.Stop();
// This is the only writing process to that int, so an update is safe.
MaxProcessingTimes[id] = Math.Max(MaxProcessingTimes[id], (int)sw_processing.ElapsedMilliseconds);
sw_write?.Start();
// Send the block to the `BlockManager` process.
@@ -22,6 +22,7 @@
using System;
using System.Diagnostics;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using CoCoL;
using Duplicati.Library.Main.Volumes;
@@ -41,6 +42,15 @@ namespace Duplicati.Library.Main.Operation.Restore
/// </summary>
private static readonly string LOGTAG = Logging.Log.LogTagFromType<VolumeDecryptor>();
/// <summary>
/// Id of the next decryptor. Used to give each decryptor a unique index.
/// </summary>
public static int IdCounter = -1;
/// <summary>
/// Maximum processing times for each active decryptor.
/// </summary>
public static int[] MaxProcessingTimes = [];
/// <summary>
/// Runs the volume decryptor process.
/// </summary>
@@ -62,6 +72,10 @@ namespace Duplicati.Library.Main.Operation.Restore
Stopwatch? sw_decrypt = options.InternalProfiling ? new() : null;
Stopwatch? sw_bvr = options.InternalProfiling ? new() : null;
Stopwatch? sw_vw = options.InternalProfiling ? new() : null;
Stopwatch sw_processing = new();
int id = Interlocked.Increment(ref IdCounter);
try
{
while (true)
@@ -72,6 +86,8 @@ namespace Duplicati.Library.Main.Operation.Restore
sw_read?.Stop();
Logging.Log.WriteExplicitMessage(LOGTAG, "DecryptVolume", null, "Decrypting volume {0} (ID: {1})", volume_name, volume_id);
sw_processing.Restart();
// Decrypt the volume.
sw_decrypt?.Start();
var tmpfile = backend.DecryptFile(volume, volume_name, options);
sw_decrypt?.Stop();
@@ -85,6 +101,9 @@ namespace Duplicati.Library.Main.Operation.Restore
var volume_wrapper = new VolumeWrapper(tmpfile, bvr);
sw_vw?.Stop();
Logging.Log.WriteExplicitMessage(LOGTAG, "BlockVolumeReader", null, "Created BlockVolumeReader for volume {0} (ID: {1})", volume_name, volume_id);
sw_processing.Stop();
// This is the only writing process to that int, so an update is safe.
MaxProcessingTimes[id] = Math.Max(MaxProcessingTimes[id], (int)sw_processing.ElapsedMilliseconds);
sw_write?.Start();
// Pass the decrypted volume to the `VolumeDecompressor` process.
@@ -43,6 +43,16 @@ namespace Duplicati.Library.Main.Operation.Restore
/// </summary>
private static readonly string LOGTAG = Logging.Log.LogTagFromType<VolumeDownloader>();
/// <summary>
/// Id of the next downloader. Used to give each downloader a unique index.
/// </summary>
public static int IdCounter = -1;
/// <summary>
/// Maximum processing times for each active downloader.
/// </summary>
public static int[] MaxProcessingTimes = [];
/// <summary>
/// Runs the volume downloader process.
/// </summary>
@@ -65,6 +75,9 @@ namespace Duplicati.Library.Main.Operation.Restore
Stopwatch? sw_write = options.InternalProfiling ? new() : null;
Stopwatch? sw_wait = options.InternalProfiling ? new() : null;
Stopwatch sw_processing = new();
var id = Interlocked.Increment(ref IdCounter);
try
{
while (true)
@@ -77,6 +90,7 @@ namespace Duplicati.Library.Main.Operation.Restore
// Trigger the download.
sw_wait?.Start();
sw_processing.Restart();
TempFile f;
var (volume_name, size, hash) = await db
.GetVolumeInfo(volume_id, results.TaskControl.ProgressToken)
@@ -93,6 +107,9 @@ namespace Duplicati.Library.Main.Operation.Restore
throw;
}
sw_processing.Stop();
// This is the only writing process to that int, so an update is safe.
MaxProcessingTimes[id] = Math.Max(MaxProcessingTimes[id], (int)sw_processing.ElapsedMilliseconds);
sw_wait?.Stop();
Logging.Log.WriteExplicitMessage(LOGTAG, "DownloadVolume", null, "Downloaded volume {0} (ID: {1})", volume_name, volume_id);