Use a more precise mechanism to measure elapsed times in operations.

This commit is contained in:
2023-09-26 20:16:24 +01:00
parent 8786474169
commit 09a5c00891
38 changed files with 692 additions and 597 deletions

View File

@@ -157,7 +157,6 @@ partial class Dump
Dictionary<byte, int> smallestPregapLbaPerTrack)
{
ulong sectorSpeedStart = 0; // Used to calculate correct speed
DateTime timeSpeedStart = DateTime.UtcNow; // Time of start for speed calculation
bool sense; // Sense indicator
byte[] cmdBuf; // Data buffer
byte[] senseBuf; // Sense buffer
@@ -247,7 +246,7 @@ partial class Dump
mhddLog.Write(i + r, cmdDuration);
ibgLog.Write(i + r, currentSpeed * 1024);
extents.Add(i + r, 1, true);
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(cdiReadyReadAsAudio)
FixOffsetData(offsetBytes, sectorSize, sectorsForOffset, supportedSubchannel,
@@ -285,7 +284,7 @@ partial class Dump
else
outputOptical.WriteSectorsLong(cmdBuf, i + r, 1);
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
_mediaGraph?.PaintSectorGood(i + r);
}
@@ -305,20 +304,23 @@ partial class Dump
break;
}
_writeStopwatch.Stop();
sectorSpeedStart += r;
_resume.NextBlock = i + r;
elapsed = (DateTime.UtcNow - timeSpeedStart).TotalSeconds;
elapsed = _speedStopwatch.Elapsed.TotalSeconds;
if(elapsed <= 0)
continue;
currentSpeed = sectorSpeedStart * blockSize / (1048576 * elapsed);
sectorSpeedStart = 0;
timeSpeedStart = DateTime.UtcNow;
_speedStopwatch.Restart();
}
_speedStopwatch.Restart();
if(!sense &&
!_dev.Error)
{
@@ -329,7 +331,7 @@ partial class Dump
mhddLog.Write(i, cmdDuration);
ibgLog.Write(i, currentSpeed * 1024);
extents.Add(i, blocksToRead, true);
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -398,7 +400,7 @@ partial class Dump
outputOptical.WriteSectorsLong(cmdBuf, i, blocksToRead);
}
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
_mediaGraph?.PaintSectorsGood(i, blocksToRead);
}
@@ -411,20 +413,22 @@ partial class Dump
break;
}
_writeStopwatch.Stop();
sectorSpeedStart += blocksToRead;
_resume.NextBlock = i + blocksToRead;
elapsed = (DateTime.UtcNow - timeSpeedStart).TotalSeconds;
elapsed = _speedStopwatch.Elapsed.TotalSeconds;
if(elapsed <= 0)
continue;
currentSpeed = sectorSpeedStart * blockSize / (1048576 * elapsed);
sectorSpeedStart = 0;
timeSpeedStart = DateTime.UtcNow;
_speedStopwatch.Restart();
}
_speedStopwatch.Stop();
EndProgress?.Invoke();
}
}

View File

@@ -101,7 +101,6 @@ partial class Dump
Dictionary<byte, int> smallestPregapLbaPerTrack)
{
ulong sectorSpeedStart = 0; // Used to calculate correct speed
DateTime timeSpeedStart = DateTime.UtcNow; // Time of start for speed calculation
uint blocksToRead; // How many sectors to read at once
bool sense = true; // Sense indicator
byte[] cmdBuf = null; // Data buffer
@@ -129,6 +128,8 @@ partial class Dump
for(ulong i = _resume.NextBlock; (long)i <= lastSector; i += blocksToRead)
{
_speedStopwatch.Restart();
if(_aborted)
{
currentTry.Extents = ExtentsConverter.ToMetadata(extents);
@@ -422,6 +423,8 @@ partial class Dump
!nextData &&
sense)
{
_speedStopwatch.Restart();
for(uint r = 0; r < blocksToRead; r++)
{
UpdateProgress?.
@@ -481,7 +484,7 @@ partial class Dump
mhddLog.Write(i + r, cmdDuration);
ibgLog.Write(i + r, currentSpeed * 1024);
extents.Add(i + r, 1, true);
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -559,14 +562,14 @@ partial class Dump
_mediaGraph?.PaintSectorGood(i + r);
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
}
else
{
_errorLog?.WriteLine(i + r, _dev.Error, _dev.LastError, senseBuf);
// Write empty data
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -589,7 +592,7 @@ partial class Dump
}
}
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
_mediaGraph?.PaintSectorBad(i + r);
@@ -605,18 +608,20 @@ partial class Dump
newTrim = true;
}
_writeStopwatch.Stop();
sectorSpeedStart += r;
_resume.NextBlock = i + r;
elapsed = (DateTime.UtcNow - timeSpeedStart).TotalSeconds;
elapsed = _speedStopwatch.Elapsed.TotalSeconds;
if(elapsed <= 0)
continue;
currentSpeed = sectorSpeedStart * blockSize / (1048576 * elapsed);
sectorSpeedStart = 0;
timeSpeedStart = DateTime.UtcNow;
_speedStopwatch.Restart();
}
continue;
@@ -641,7 +646,7 @@ partial class Dump
mhddLog.Write(i, cmdDuration, blocksToRead);
ibgLog.Write(i, currentSpeed * 1024);
extents.Add(i, blocksToRead, true);
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -722,7 +727,7 @@ partial class Dump
_mediaGraph?.PaintSectorsGood(i, blocksToRead);
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
}
else
{
@@ -747,7 +752,7 @@ partial class Dump
_skip = (uint)(blocks - i);
// Write empty data
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -770,7 +775,7 @@ partial class Dump
}
}
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
for(ulong b = i; b < i + _skip; b++)
_resume.BadBlocks.Add(b);
@@ -784,20 +789,23 @@ partial class Dump
newTrim = true;
}
_writeStopwatch.Stop();
sectorSpeedStart += blocksToRead;
_resume.NextBlock = i + blocksToRead;
elapsed = (DateTime.UtcNow - timeSpeedStart).TotalSeconds;
elapsed = _speedStopwatch.Elapsed.TotalSeconds;
if(elapsed <= 0)
continue;
currentSpeed = sectorSpeedStart * blockSize / (1048576 * elapsed);
sectorSpeedStart = 0;
timeSpeedStart = DateTime.UtcNow;
_speedStopwatch.Restart();
}
_speedStopwatch.Stop();
EndProgress?.Invoke();
_resume.BadBlocks = _resume.BadBlocks.Distinct().ToList();

View File

@@ -75,9 +75,7 @@ sealed partial class Dump
DumpHardware currentTry = null; // Current dump hardware try
double currentSpeed = 0; // Current read speed
int? discOffset = null; // Disc write offset
DateTime dumpStart = DateTime.UtcNow; // Time of dump start
DateTime end; // Time of operation end
ExtentsULong extents = null; // Extents
ExtentsULong extents = null; // Extents
bool hiddenData; // Hidden track is data
IbgLog ibgLog; // IMGBurn log
double imageWriteDuration = 0; // Duration of image write
@@ -99,7 +97,6 @@ sealed partial class Dump
int sectorsForOffset = 0; // Sectors needed to fix offset
bool sense = true; // Sense indicator
int sessions; // Number of sessions in disc
DateTime start; // Start of operation
SubchannelLog subLog = null; // Subchannel log
uint subSize = 0; // Subchannel size in bytes
TrackSubchannelType subType = TrackSubchannelType.None; // Track subchannel type
@@ -1167,7 +1164,7 @@ sealed partial class Dump
}
// Start reading
start = DateTime.UtcNow;
_dumpStopwatch.Restart();
if(dskType == MediaType.CDIREADY || cdiWithHiddenTrack1)
{
@@ -1289,14 +1286,14 @@ sealed partial class Dump
smallestPregapLbaPerTrack);
*/
end = DateTime.UtcNow;
_dumpStopwatch.Stop();
mhddLog.Close();
ibgLog.Close(_dev, blocks, blockSize, (end - start).TotalSeconds, currentSpeed * 1024,
ibgLog.Close(_dev, blocks, blockSize, _dumpStopwatch.Elapsed.TotalSeconds, currentSpeed * 1024,
blockSize * (double)(blocks + 1) / 1024 / (totalDuration / 1000), _devicePath);
UpdateStatus?.Invoke(string.Format(Localization.Core.Dump_finished_in_0,
(end - start).Humanize(minUnit: TimeUnit.Second)));
_dumpStopwatch.Elapsed.Humanize(minUnit: TimeUnit.Second)));
UpdateStatus?.Invoke(string.Format(Localization.Core.Average_dump_speed_0,
ByteSize.FromBytes(blockSize * (blocks + 1)).
@@ -1307,7 +1304,7 @@ sealed partial class Dump
Per(imageWriteDuration.Seconds())));
_dumpLog.WriteLine(string.Format(Localization.Core.Dump_finished_in_0,
(end - start).Humanize(minUnit: TimeUnit.Second)));
_dumpStopwatch.Elapsed.Humanize(minUnit: TimeUnit.Second)));
_dumpLog.WriteLine(string.Format(Localization.Core.Average_dump_speed_0,
ByteSize.FromBytes(blockSize * (blocks + 1)).
@@ -1439,12 +1436,12 @@ sealed partial class Dump
_dumpLog.WriteLine(Localization.Core.Closing_output_file);
UpdateStatus?.Invoke(Localization.Core.Closing_output_file);
DateTime closeStart = DateTime.Now;
_imageCloseStopwatch.Restart();
outputOptical.Close();
DateTime closeEnd = DateTime.Now;
_imageCloseStopwatch.Stop();
UpdateStatus?.Invoke(string.Format(Localization.Core.Closed_in_0,
(closeEnd - closeStart).Humanize(minUnit: TimeUnit.Second)));
_imageCloseStopwatch.Elapsed.Humanize(minUnit: TimeUnit.Second)));
subLog?.Close();
@@ -1461,16 +1458,16 @@ sealed partial class Dump
WriteOpticalSidecar(blockSize, blocks, dskType, null, mediaTags, sessions, out totalChkDuration,
discOffset);
end = DateTime.UtcNow;
_dumpStopwatch.Stop();
UpdateStatus?.Invoke("");
UpdateStatus?.
Invoke(string.Format(Localization.Core.Took_a_total_of_0_1_processing_commands_2_checksumming_3_writing_4_closing,
(end - start).Humanize(minUnit: TimeUnit.Second),
_dumpStopwatch.Elapsed.Humanize(minUnit: TimeUnit.Second),
totalDuration.Milliseconds().Humanize(minUnit: TimeUnit.Second),
totalChkDuration.Milliseconds().Humanize(minUnit: TimeUnit.Second),
imageWriteDuration.Seconds().Humanize(minUnit: TimeUnit.Second),
(closeEnd - closeStart).Humanize(minUnit: TimeUnit.Second)));
_imageCloseStopwatch.Elapsed.Humanize(minUnit: TimeUnit.Second)));
UpdateStatus?.Invoke(string.Format(Localization.Core.Average_speed_0,
ByteSize.FromBytes(blockSize * (blocks + 1)).

View File

@@ -151,7 +151,7 @@ partial class Dump
ibgLog.Write(i, currentSpeed * 1024);
extents.Add(i, _maximumReadable, true);
leadOutExtents.Remove(i);
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -184,7 +184,7 @@ partial class Dump
else
outputOptical.WriteSectors(cmdBuf, i, _maximumReadable);
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
}
else
{
@@ -195,7 +195,7 @@ partial class Dump
return; // TODO: Return more cleanly
// Write empty data
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -207,13 +207,14 @@ partial class Dump
else
outputOptical.WriteSectors(new byte[blockSize * _skip], i, 1);
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
mhddLog.Write(i, cmdDuration < 500 ? 65535 : cmdDuration, _skip);
ibgLog.Write(i, 0);
}
_writeStopwatch.Stop();
double newSpeed = (double)blockSize * _maximumReadable / 1048576 / (cmdDuration / 1000);
if(!double.IsInfinity(newSpeed))
@@ -323,7 +324,7 @@ partial class Dump
ibgLog.Write(i, currentSpeed * 1024);
extents.Add(i, _maximumReadable, true);
leadOutExtents.Remove(i);
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -356,7 +357,7 @@ partial class Dump
else
outputOptical.WriteSectors(cmdBuf, i, _maximumReadable);
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
}
else
{
@@ -367,7 +368,7 @@ partial class Dump
return; // TODO: Return more cleanly
// Write empty data
DateTime writeStart = DateTime.Now;
_writeStopwatch.Restart();
if(supportedSubchannel != MmcSubchannel.None)
{
@@ -380,13 +381,14 @@ partial class Dump
else
outputOptical.WriteSectors(new byte[blockSize * _skip], i, 1);
imageWriteDuration += (DateTime.Now - writeStart).TotalSeconds;
imageWriteDuration += _writeStopwatch.Elapsed.TotalSeconds;
mhddLog.Write(i, cmdDuration < 500 ? 65535 : cmdDuration);
ibgLog.Write(i, 0);
}
_writeStopwatch.Stop();
double newSpeed = (double)blockSize * _maximumReadable / 1048576 / (cmdDuration / 1000);
if(!double.IsInfinity(newSpeed))

View File

@@ -65,7 +65,6 @@ partial class Dump
bool sense; // Sense indicator
byte[] cmdBuf; // Data buffer
double cmdDuration; // Command execution time
DateTime timeSpeedStart; // Time of start for speed calculation
ulong sectorSpeedStart = 0; // Used to calculate correct speed
bool gotFirstTrackPregap = false;
int firstTrackPregapSectorsGood = 0;
@@ -74,7 +73,7 @@ partial class Dump
_dumpLog.WriteLine(Localization.Core.Reading_first_track_pregap);
UpdateStatus?.Invoke(Localization.Core.Reading_first_track_pregap);
InitProgress?.Invoke();
timeSpeedStart = DateTime.UtcNow;
_speedStopwatch.Restart();
for(int firstTrackPregapBlock = -150; firstTrackPregapBlock < 0 && _resume.NextBlock == 0;
firstTrackPregapBlock++)
@@ -115,16 +114,18 @@ partial class Dump
sectorSpeedStart++;
double elapsed = (DateTime.UtcNow - timeSpeedStart).TotalSeconds;
double elapsed = _speedStopwatch.Elapsed.TotalSeconds;
if(elapsed <= 0)
continue;
currentSpeed = sectorSpeedStart * blockSize / (1048576 * elapsed);
sectorSpeedStart = 0;
timeSpeedStart = DateTime.UtcNow;
_speedStopwatch.Restart();
}
_speedStopwatch.Stop();
if(firstTrackPregapSectorsGood > 0)
mediaTags.Add(MediaTagType.CD_FirstTrackPregap, firstTrackPregapMs.ToArray());

View File

@@ -83,8 +83,6 @@ partial class Dump
Dictionary<byte, string> isrcs, ref string mcn, HashSet<int> subchannelExtents,
Dictionary<byte, int> smallestPregapLbaPerTrack)
{
DateTime start;
DateTime end;
bool sense = true; // Sense indicator
byte[] cmdBuf = null; // Data buffer
double cmdDuration = 0; // Command execution time
@@ -107,10 +105,10 @@ partial class Dump
!newTrim)
return;
start = DateTime.UtcNow;
UpdateStatus?.Invoke(Localization.Core.Trimming_skipped_sectors);
_dumpLog.WriteLine(Localization.Core.Trimming_skipped_sectors);
InitProgress?.Invoke();
_trimStopwatch.Restart();
trimStart:
ulong[] tmpArray = _resume.BadBlocks.ToArray();
@@ -292,13 +290,13 @@ partial class Dump
outputOptical.WriteSector(Sector.GetUserData(cmdBuf), badSector);
}
_trimStopwatch.Stop();
EndProgress?.Invoke();
end = DateTime.UtcNow;
UpdateStatus?.Invoke(string.Format(Localization.Core.Trimming_finished_in_0,
(end - start).Humanize(minUnit: TimeUnit.Second)));
_trimStopwatch.Elapsed.Humanize(minUnit: TimeUnit.Second)));
_dumpLog.WriteLine(string.Format(Localization.Core.Trimming_finished_in_0,
(end - start).Humanize(minUnit: TimeUnit.Second)));
_trimStopwatch.Elapsed.Humanize(minUnit: TimeUnit.Second)));
}
}