Added profile logging to all commit calls

Added extra profiling on backup
This commit is contained in:
Kenneth Skovhede
2013-06-09 16:30:28 +02:00
parent c44361a039
commit 2b01d20ce3
8 changed files with 124 additions and 82 deletions
@@ -358,7 +358,9 @@ namespace Duplicati.Library.Main.Database
using (var tr = new TemporaryTransactionWrapper(m_connection, transaction))
{
m_insertblocksetCommand.Transaction = tr.Parent;
blocksetid = Convert.ToInt64(m_insertblocksetCommand.ExecuteScalar(null, size, filehash));
m_insertblocksetCommand.SetParameterValue(0, size);
m_insertblocksetCommand.SetParameterValue(1, filehash);
blocksetid = Convert.ToInt64(m_insertblocksetCommand.ExecuteScalar());
if (m_fileHashLookup != null)
m_fileHashLookup.Add(hashdata, filehash, blocksetid);
@@ -394,7 +396,8 @@ namespace Duplicati.Library.Main.Database
remainsize -= blocksize;
}
tr.Commit();
using(new Logging.Timer("CommitAddBlockset"))
tr.Commit();
}
return true;
@@ -470,8 +473,10 @@ namespace Duplicati.Library.Main.Database
using (var tr = new TemporaryTransactionWrapper(m_connection, transaction))
{
m_insertmetadatasetCommand.Transaction = tr.Parent;
metadataid = Convert.ToInt64(m_insertmetadatasetCommand.ExecuteScalar(null, blocksetid));
tr.Commit();
m_insertmetadatasetCommand.SetParameterValue(0, blocksetid);
metadataid = Convert.ToInt64(m_insertmetadatasetCommand.ExecuteScalar());
using(new Logging.Timer("CommitAddMetadataset"))
tr.Commit();
if (m_metadataLookup != null)
m_metadataLookup.Add(hashdata, hash, metadataid);
}
@@ -547,7 +552,8 @@ namespace Duplicati.Library.Main.Database
m_insertfileCommand.SetParameterValue(1, blocksetID);
m_insertfileCommand.SetParameterValue(2, metadataID);
fileidobj = Convert.ToInt64(m_insertfileCommand.ExecuteScalar());
tr.Commit();
using(new Logging.Timer("CommitAddFile"))
tr.Commit();
// We do not need to update this, because we will not ask for the same file twice
if (m_filesetLookup != null)
@@ -784,7 +790,8 @@ namespace Duplicati.Library.Main.Database
}
}
tr.Commit();
using(new Logging.Timer("CommitAppendFilesFromPrevious"))
tr.Commit();
}
}
@@ -801,7 +808,8 @@ namespace Duplicati.Library.Main.Database
{
cmd.Transaction = tr.Parent;
m_filesetId = Convert.ToInt64(cmd.ExecuteScalar(@"INSERT INTO ""Fileset"" (""OperationID"", ""Timestamp"", ""VolumeID"") VALUES (?, ?, ?); SELECT last_insert_rowid();", m_operationid, timestamp, volumeid));
tr.Commit();
using(new Logging.Timer("CommitCreateFileset"))
tr.Commit();
return m_filesetId;
}
}
@@ -49,7 +49,8 @@ namespace Duplicati.Library.Main.Database
cmd.ExecuteNonQuery(@"UPDATE ""LogData"" SET ""Exception"" = ""ERASED!"" WHERE ""Exception"" LIKE ""%/%"" OR ""Exception"" LIKE ""%:\%"" ");
cmd.ExecuteNonQuery(@"UPDATE ""File"" SET ""Path"" = ""ID"" ");
tr.Commit();
using(new Logging.Timer("CommitUpdateBugReport"))
tr.Commit();
cmd.Transaction = null;
cmd.ExecuteNonQuery("VACUUM");
@@ -306,7 +306,8 @@ namespace Duplicati.Library.Main.Database
m_removeremotevolumeCommand.Transaction = tr.Parent;
m_removeremotevolumeCommand.ExecuteNonQuery();
tr.Commit();
using(new Logging.Timer("CommitRemoveRemoteVolume"))
tr.Commit();
}
}
@@ -320,7 +321,8 @@ namespace Duplicati.Library.Main.Database
m_createremotevolumeCommand.SetParameterValue(3, state.ToString());
m_createremotevolumeCommand.Transaction = tr.Parent;
var r = Convert.ToInt64(m_createremotevolumeCommand.ExecuteScalar());
tr.Commit();
using(new Logging.Timer("CommitRegisterVolume"))
tr.Commit();
return r;
}
}
@@ -482,7 +484,8 @@ namespace Duplicati.Library.Main.Database
foreach(var kp in options)
cmd.ExecuteNonQuery(@"INSERT INTO ""Configuration"" (""Key"", ""Value"") VALUES (?, ?) ", kp.Key, kp.Value);
tr.Commit();
using(new Logging.Timer("CommitSetDbOptions"))
tr.Commit();
}
}
@@ -755,7 +758,8 @@ namespace Duplicati.Library.Main.Database
}
tr.Commit();
using(new Logging.Timer("CreateFilenameTable"))
tr.Commit();
}
}
}
@@ -94,7 +94,8 @@ namespace Duplicati.Library.Main.Database
cmd.ExecuteNonQuery(string.Format(@"DROP TABLE ""{0}"" ", m_filenamestable));
tr.Commit();
using(new Logging.Timer("CommitPrepareFileset"))
tr.Commit();
}
}
else
@@ -436,7 +437,8 @@ namespace Duplicati.Library.Main.Database
var tr = m_insertblockCommand.Transaction;
m_insertblockCommand.Dispose();
m_insertblockCommand = null;
tr.Commit();
using(new Logging.Timer("CommitBlockMarker"))
tr.Commit();
tr.Dispose();
}
@@ -117,23 +117,26 @@ namespace Duplicati.Library.Main.Operation
{
if (!m_options.NoBackendverification)
{
try
using(new Logging.Timer("PreBackupVerify"))
{
FilelistProcessor.VerifyRemoteList(m_backend, m_options, m_database, m_result.BackendWriter);
}
catch (Exception ex)
{
if (m_options.AutoCleanup)
try
{
m_result.AddWarning("Backend verification failed, attempting automatic cleanup", ex);
m_result.RepairResults = new RepairResults(m_result);
new RepairHandler(m_backend.BackendUrl, m_options, (RepairResults)m_result.RepairResults).Run();
m_result.AddMessage("Backend cleanup finished, retrying verification");
FilelistProcessor.VerifyRemoteList(m_backend, m_options, m_database, m_result.BackendWriter);
}
else
throw;
catch (Exception ex)
{
if (m_options.AutoCleanup)
{
m_result.AddWarning("Backend verification failed, attempting automatic cleanup", ex);
m_result.RepairResults = new RepairResults(m_result);
new RepairHandler(m_backend.BackendUrl, m_options, (RepairResults)m_result.RepairResults).Run();
m_result.AddMessage("Backend cleanup finished, retrying verification");
FilelistProcessor.VerifyRemoteList(m_backend, m_options, m_database, m_result.BackendWriter);
}
else
throw;
}
}
}
@@ -166,6 +169,7 @@ namespace Duplicati.Library.Main.Operation
return true;
};
using(new Logging.Timer("BackupMainOperation"))
using(m_snapshot = GetSnapshot(sources, m_options, m_result))
{
if (m_options.ChangedFilelist != null && m_options.ChangedFilelist.Length >= 1)
@@ -210,40 +214,46 @@ namespace Duplicati.Library.Main.Operation
}
}
if (m_blockvolume.SourceSize > 0)
using(new Logging.Timer("FinalizeRemoteVolumes"))
{
lastVolumeSize = m_blockvolume.SourceSize;
if (m_options.Dryrun)
if (m_blockvolume.SourceSize > 0)
{
m_result.AddDryrunMessage(string.Format("Would upload block volume: {0}, size: {1}", m_blockvolume.RemoteFilename, Library.Utility.Utility.FormatSizeString(new FileInfo(m_blockvolume.LocalFilename).Length)));
if (m_indexvolume != null)
lastVolumeSize = m_blockvolume.SourceSize;
if (m_options.Dryrun)
{
m_result.AddDryrunMessage(string.Format("Would upload block volume: {0}, size: {1}", m_blockvolume.RemoteFilename, Library.Utility.Utility.FormatSizeString(new FileInfo(m_blockvolume.LocalFilename).Length)));
if (m_indexvolume != null)
{
UpdateIndexVolume();
m_indexvolume.FinishVolume(Library.Utility.Utility.CalculateHash(m_blockvolume.LocalFilename), new FileInfo(m_blockvolume.LocalFilename).Length);
m_result.AddDryrunMessage(string.Format("Would upload index volume: {0}, size: {1}", m_indexvolume.RemoteFilename, Library.Utility.Utility.FormatSizeString(new FileInfo(m_indexvolume.LocalFilename).Length)));
}
}
else
{
m_database.UpdateRemoteVolume(m_blockvolume.RemoteFilename, RemoteVolumeState.Uploading, -1, null, m_transaction);
UpdateIndexVolume();
m_indexvolume.FinishVolume(Library.Utility.Utility.CalculateHash(m_blockvolume.LocalFilename), new FileInfo(m_blockvolume.LocalFilename).Length);
m_result.AddDryrunMessage(string.Format("Would upload index volume: {0}, size: {1}", m_indexvolume.RemoteFilename, Library.Utility.Utility.FormatSizeString(new FileInfo(m_indexvolume.LocalFilename).Length)));
using(new Logging.Timer("CommitUpdateRemoteVolume"))
m_transaction.Commit();
m_transaction = m_database.BeginTransaction();
m_backend.Put(m_blockvolume, m_indexvolume);
}
}
else
{
m_database.UpdateRemoteVolume(m_blockvolume.RemoteFilename, RemoteVolumeState.Uploading, -1, null, m_transaction);
UpdateIndexVolume();
m_transaction.Commit();
m_transaction = m_database.BeginTransaction();
m_backend.Put(m_blockvolume, m_indexvolume);
m_database.RemoveRemoteVolume(m_blockvolume.RemoteFilename, m_transaction);
if (m_indexvolume != null)
m_database.RemoveRemoteVolume(m_indexvolume.RemoteFilename, m_transaction);
}
}
else
{
m_database.RemoveRemoteVolume(m_blockvolume.RemoteFilename, m_transaction);
if (m_indexvolume != null)
m_database.RemoveRemoteVolume(m_indexvolume.RemoteFilename, m_transaction);
}
m_database.UpdateChangeStatistics(m_result);
m_database.VerifyConsistency(m_transaction);
using(new Logging.Timer("UpdateChangeStatistics"))
m_database.UpdateChangeStatistics(m_result);
using(new Logging.Timer("VerifyConsistency"))
m_database.VerifyConsistency(m_transaction);
//Changes in the filelist triggers a filelist upload
if (m_options.UploadUnchangedBackups ||
@@ -251,21 +261,25 @@ namespace Duplicati.Library.Main.Operation
m_result.AddedFolders + m_result.ModifiedFolders + m_result.DeletedFolders +
m_result.AddedSymlinks + m_result.ModifiedSymlinks + m_result.DeletedSymlinks) > 0)
{
if (!string.IsNullOrEmpty(m_options.ControlFiles))
foreach(var p in m_options.ControlFiles.Split(new char[] { System.IO.Path.PathSeparator }, StringSplitOptions.RemoveEmptyEntries))
m_filesetvolume.AddControlFile(p, m_options.GetCompressionHintFromFilename(p));
m_database.WriteFileset(m_filesetvolume, m_transaction);
if (m_options.Dryrun)
m_result.AddDryrunMessage(string.Format("Would upload fileset volume: {0}, size: {1}", m_filesetvolume.RemoteFilename, Library.Utility.Utility.FormatSizeString(new FileInfo(m_filesetvolume.LocalFilename).Length)));
else
using(new Logging.Timer("Uploading a new fileset"))
{
m_database.UpdateRemoteVolume(m_filesetvolume.RemoteFilename, RemoteVolumeState.Uploading, -1, null, m_transaction);
m_transaction.Commit();
m_transaction = m_database.BeginTransaction();
m_backend.Put(m_filesetvolume);
if (!string.IsNullOrEmpty(m_options.ControlFiles))
foreach(var p in m_options.ControlFiles.Split(new char[] { System.IO.Path.PathSeparator }, StringSplitOptions.RemoveEmptyEntries))
m_filesetvolume.AddControlFile(p, m_options.GetCompressionHintFromFilename(p));
m_database.WriteFileset(m_filesetvolume, m_transaction);
if (m_options.Dryrun)
m_result.AddDryrunMessage(string.Format("Would upload fileset volume: {0}, size: {1}", m_filesetvolume.RemoteFilename, Library.Utility.Utility.FormatSizeString(new FileInfo(m_filesetvolume.LocalFilename).Length)));
else
{
m_database.UpdateRemoteVolume(m_filesetvolume.RemoteFilename, RemoteVolumeState.Uploading, -1, null, m_transaction);
using(new Logging.Timer("CommitUpdateRemoteVolume"))
m_transaction.Commit();
m_transaction = m_database.BeginTransaction();
m_backend.Put(m_filesetvolume);
}
}
}
else
@@ -274,7 +288,8 @@ namespace Duplicati.Library.Main.Operation
m_database.RemoveRemoteVolume(m_filesetvolume.RemoteFilename, m_transaction);
}
m_backend.WaitForComplete(m_database, m_transaction);
using(new Logging.Timer("Async backend wait"))
m_backend.WaitForComplete(m_database, m_transaction);
if (m_options.KeepTime.Ticks > 0 || m_options.KeepVersions != 0)
@@ -298,11 +313,13 @@ namespace Duplicati.Library.Main.Operation
}
else
{
m_transaction.Commit();
using(new Logging.Timer("CommitFinalizingBackup"))
m_transaction.Commit();
m_transaction = null;
using(var backend = new BackendManager(m_backendurl, m_options, m_result.BackendWriter, m_database))
{
FilelistProcessor.VerifyRemoteList(backend, m_options, m_database, m_result.BackendWriter);
using(new Logging.Timer("AfterBackupVerify"))
FilelistProcessor.VerifyRemoteList(backend, m_options, m_database, m_result.BackendWriter);
backend.WaitForComplete(m_database, null);
}
}
@@ -586,7 +603,8 @@ namespace Duplicati.Library.Main.Operation
m_backend.FlushDbMessages(m_database, m_transaction);
m_backendLogFlushTimer = DateTime.Now.Add(FLUSH_TIMESPAN);
m_transaction.Commit();
using(new Logging.Timer("CommitAddBlockToOutputFlush"))
m_transaction.Commit();
m_transaction = m_database.BeginTransaction();
m_backend.Put(m_blockvolume, m_indexvolume);
@@ -38,19 +38,22 @@ namespace Duplicati.Library.Main.Operation
}
public virtual void Run()
{
if (!System.IO.File.Exists(m_options.Dbpath))
throw new Exception(string.Format("Database file does not exist: {0}", m_options.Dbpath));
{
if (!System.IO.File.Exists(m_options.Dbpath))
throw new Exception(string.Format("Database file does not exist: {0}", m_options.Dbpath));
using(var db = new LocalDeleteDatabase(m_options.Dbpath, true))
using(var tr = db.BeginTransaction())
{
using(var db = new LocalDeleteDatabase(m_options.Dbpath, true))
using(var tr = db.BeginTransaction())
{
m_result.SetDatabase(db);
Utility.VerifyParameters(db, m_options);
Utility.VerifyParameters(db, m_options);
DoCompact(db, false, tr);
if (!m_options.Dryrun)
tr.Commit();
DoCompact(db, false, tr);
if (!m_options.Dryrun)
{
using(new Logging.Timer("CommitCompact"))
tr.Commit();
}
else
tr.Rollback();
}
@@ -50,7 +50,10 @@ namespace Duplicati.Library.Main.Operation
DoRun(db, tr, false, false);
if (!m_options.Dryrun)
tr.Commit();
{
using(new Logging.Timer("CommitDelete"))
tr.Commit();
}
else
tr.Rollback();
}
@@ -149,7 +149,8 @@ namespace Duplicati.Library.Main.Operation
}
}
tr.Commit();
using(new Logging.Timer("CommitRecreatedDb"))
tr.Commit();
}
//We need this to prepare for the block-lists
@@ -192,7 +193,8 @@ namespace Duplicati.Library.Main.Operation
}
}
tr.Commit();
using(new Logging.Timer("CommitUpdateFilesetFromRemote"))
tr.Commit();
}
}
@@ -211,7 +213,8 @@ namespace Duplicati.Library.Main.Operation
foreach (var blocklisthash in restoredb.GetBlockLists(volumeid))
restoredb.UpdateBlocklist(blocklisthash, rd.ReadBlocklist(blocklisthash, hashsize), hashsize, tr);
tr.Commit();
using(new Logging.Timer("CommitRestoredBlocklist"))
tr.Commit();
//At this point we can patch files with data from the block volume
if (blockprocessor != null)