Moved formatting of the explicit log messages to occur later to alleviate having to do that when that log level is disabled, which should decrease wasted processing.
This commit is contained in:
Carl Johnsen
@@ -144,7 +144,7 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
m_entry_options.RegisterPostEvictionCallback((key, value, reason, state) =>
|
||||
{
|
||||
Interlocked.Decrement(ref m_block_cache_count);
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "CacheEvictCallback", $"Evicted block {key} from cache");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "CacheEvictCallback", "Evicted block {0} from cache", key);
|
||||
});
|
||||
m_readers = readers;
|
||||
sw_cacheevict = options.InternalProfiling ? new() : null;
|
||||
@@ -240,12 +240,12 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
|
||||
if (error_block_id != -1)
|
||||
{
|
||||
Logging.Log.WriteWarningMessage(LOGTAG, "BlockCountError", null, $"Block {blockRequest.BlockID} has a count below 0");
|
||||
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 {blockRequest.VolumeID} has a count below 0");
|
||||
Logging.Log.WriteWarningMessage(LOGTAG, "VolumeCountError", null, "Volume {0} has a count below 0", blockRequest.VolumeID);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -454,7 +454,7 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
var (block_request, data) = await self.Input.ReadAsync().ConfigureAwait(false);
|
||||
sw_read?.Stop();
|
||||
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "VolumeConsumer", null, $"Received block request: {block_request.RequestType} for block {block_request.BlockID} from volume {block_request.VolumeID}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "VolumeConsumer", null, "Received block request: {0} for block {1} from volume {2}", block_request.RequestType, block_request.BlockID, block_request.VolumeID);
|
||||
sw_ack?.Start();
|
||||
block_request.RequestType = BlockRequestType.DecompressAck;
|
||||
while (true)
|
||||
@@ -466,7 +466,7 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
}
|
||||
sw_ack?.Stop();
|
||||
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "VolumeConsumer", null, $"Received data for block {block_request.BlockID} from volume {block_request.VolumeID}");
|
||||
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();
|
||||
@@ -509,19 +509,19 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
sw_req?.Start();
|
||||
var block_request = await req.ReadAsync().ConfigureAwait(false);
|
||||
sw_req?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "BlockHandler", null, $"Received block request: {block_request.RequestType}");
|
||||
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 {block_request.BlockID} and volume {block_request.VolumeID}");
|
||||
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 {block_request.BlockID} and volume {block_request.VolumeID} to FileProcessor");
|
||||
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();
|
||||
@@ -529,7 +529,7 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
await cache.CheckCounts(block_request).ConfigureAwait(false);
|
||||
sw_cache?.Stop();
|
||||
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "BlockHandler", null, $"Decremented counts for block {block_request.BlockID} and volume {block_request.VolumeID}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "BlockHandler", null, "Decremented counts for block {0} and volume {1}", block_request.BlockID, block_request.VolumeID);
|
||||
break;
|
||||
case BlockRequestType.DecompressAck:
|
||||
default:
|
||||
|
||||
@@ -115,7 +115,7 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
var file = await self.Input.ReadAsync().ConfigureAwait(false);
|
||||
sw_file?.Stop();
|
||||
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "FileRestored", null, $"{my_id} Restoring file {file.TargetPath}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "FileRestored", null, "{0} Restoring file {1}", my_id, file.TargetPath);
|
||||
|
||||
if (file.BlocksetID == LocalDatabase.FOLDER_BLOCKSET_ID && !options.SkipMetadata)
|
||||
{
|
||||
|
||||
@@ -73,12 +73,12 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
// Get the block request and volume from the `VolumeDecryptor` process.
|
||||
var (block_request, volume_reader) = await self.Input.ReadAsync().ConfigureAwait(false);
|
||||
sw_read?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", $"Decompressing block {block_request.BlockID} from volume {block_request.VolumeID}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", "Decompressing block {0} from volume {1}", block_request.BlockID, block_request.VolumeID);
|
||||
|
||||
sw_decompress_alloc?.Start();
|
||||
var data = ArrayPool<byte>.Shared.Rent(options.Blocksize);
|
||||
sw_decompress_alloc?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", $"Allocated buffer for block {block_request.BlockID} from volume {block_request.VolumeID}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", "Allocated buffer for block {0} from volume {1}", block_request.BlockID, block_request.VolumeID);
|
||||
|
||||
sw_decompress_locking?.Start();
|
||||
lock (volume_reader) // The BlockVolumeReader is not thread-safe
|
||||
@@ -88,22 +88,22 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
volume_reader.ReadBlock(block_request.BlockHash, data);
|
||||
sw_decompress_read?.Stop();
|
||||
}
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", $"Decompressed block {block_request.BlockID} from volume {block_request.VolumeID}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", "Decompressed block {0} from volume {1}", block_request.BlockID, block_request.VolumeID);
|
||||
|
||||
sw_verify?.Start();
|
||||
var hash = Convert.ToBase64String(block_hasher.ComputeHash(data, 0, (int)block_request.BlockSize));
|
||||
if (hash != block_request.BlockHash)
|
||||
{
|
||||
Logging.Log.WriteErrorMessage(LOGTAG, "InvalidBlock", null, $"Invalid block detected for block {block_request.BlockID} in volume {block_request.VolumeID}, expected hash: {block_request.BlockHash}, actual hash: {hash}");
|
||||
Logging.Log.WriteErrorMessage(LOGTAG, "InvalidBlock", null, "Invalid block detected for block {0} in volume {1}, expected hash: {2}, actual hash: {3}", block_request.BlockID, block_request.VolumeID, block_request.BlockHash, hash);
|
||||
}
|
||||
sw_verify?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", $"Verified block {block_request.BlockID} from volume {block_request.VolumeID}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", "Verified block {0} from volume {1}", block_request.BlockID, block_request.VolumeID);
|
||||
|
||||
sw_write?.Start();
|
||||
// Send the block to the `BlockManager` process.
|
||||
await self.Output.WriteAsync((block_request, data)).ConfigureAwait(false);
|
||||
sw_write?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", $"Sent block {block_request.BlockID} from volume {block_request.VolumeID} to BlockManager");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecompressBlock", "Sent block {0} from volume {1} to BlockManager", block_request.BlockID, block_request.VolumeID);
|
||||
}
|
||||
}
|
||||
catch (RetiredException)
|
||||
|
||||
@@ -69,23 +69,23 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
sw_read?.Start();
|
||||
var (volume_id, volume_name, volume) = await self.Input.ReadAsync().ConfigureAwait(false);
|
||||
sw_read?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecryptVolume", null, $"Decrypting volume {volume_name} (ID: {volume_id})");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecryptVolume", null, "Decrypting volume {0} (ID: {1})", volume_name, volume_id);
|
||||
|
||||
sw_decrypt?.Start();
|
||||
var tmpfile = backend.DecryptFile(volume, volume_name, options);
|
||||
sw_decrypt?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecryptVolume", null, $"Decrypted volume {volume_name} (ID: {volume_id})");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecryptVolume", null, "Decrypted volume {0} (ID: {1})", volume_name, volume_id);
|
||||
|
||||
sw_bvr?.Start();
|
||||
var bvr = new BlockVolumeReader(options.CompressionModule, tmpfile, options);
|
||||
sw_bvr?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "BlockVolumeReader", null, $"Created BlockVolumeReader for volume {volume_name} (ID: {volume_id})");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "BlockVolumeReader", null, "Created BlockVolumeReader for volume {0} (ID: {1})", volume_name, volume_id);
|
||||
|
||||
sw_write?.Start();
|
||||
// Pass the decrypted volume to the `VolumeDecompressor` process.
|
||||
await self.Output.WriteAsync((volume_id, tmpfile, bvr)).ConfigureAwait(false);
|
||||
sw_write?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecryptVolume", null, $"Passed decrypted volume {volume_name} (ID: {volume_id}) to next stage");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DecryptVolume", null, "Passed decrypted volume {0} (ID: {1}) to next stage", volume_name, volume_id);
|
||||
}
|
||||
}
|
||||
catch (RetiredException)
|
||||
|
||||
@@ -73,7 +73,7 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
sw_read?.Start();
|
||||
var volume_id = await self.Input.ReadAsync().ConfigureAwait(false);
|
||||
sw_read?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DownloadVolume", null, $"Downloaded volume {volume_id}");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DownloadVolume", null, "Downloaded volume {0}", volume_id);
|
||||
|
||||
// Trigger the download.
|
||||
sw_wait?.Start();
|
||||
@@ -94,13 +94,13 @@ namespace Duplicati.Library.Main.Operation.Restore
|
||||
throw;
|
||||
}
|
||||
sw_wait?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DownloadVolume", null, $"Downloaded volume {volume_name} (ID: {volume_id})");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DownloadVolume", null, "Downloaded volume {0} (ID: {1})", volume_name, volume_id);
|
||||
|
||||
// Pass the download handle (which may or may not have downloaded already) to the `VolumeDecryptor` process.
|
||||
sw_write?.Start();
|
||||
await self.Output.WriteAsync((volume_id, volume_name, f)).ConfigureAwait(false);
|
||||
sw_write?.Stop();
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DownloadVolume", null, $"Passed volume {volume_name} (ID: {volume_id}) to next stage");
|
||||
Logging.Log.WriteExplicitMessage(LOGTAG, "DownloadVolume", null, "Passed volume {0} (ID: {1}) to next stage", volume_name, volume_id);
|
||||
}
|
||||
}
|
||||
catch (RetiredException)
|
||||
|
||||
Reference in New Issue
Block a user