diff --git a/LightlessSync/Services/CharaData/CharaDataFileHandler.cs b/LightlessSync/Services/CharaData/CharaDataFileHandler.cs index 6c70157..1523e28 100644 --- a/LightlessSync/Services/CharaData/CharaDataFileHandler.cs +++ b/LightlessSync/Services/CharaData/CharaDataFileHandler.cs @@ -1,4 +1,4 @@ -using Dalamud.Game.ClientState.Objects.SubKinds; +using Dalamud.Game.ClientState.Objects.SubKinds; using K4os.Compression.LZ4.Legacy; using LightlessSync.API.Data; using LightlessSync.API.Data.Enum; @@ -185,7 +185,7 @@ public sealed class CharaDataFileHandler : IDisposable { if (charaFileHeader == null) return []; - using var lz4Stream = new LZ4Stream(File.OpenRead(charaFileHeader.FilePath), LZ4StreamMode.Decompress, LZ4StreamFlags.HighCompression); + using var lz4Stream = new LZ4Stream(File.OpenRead(charaFileHeader.FilePath), LZ4StreamMode.Decompress, LZ4StreamFlags.Default); using var reader = new BinaryReader(lz4Stream); LightlessCharaFileHeader.AdvanceReaderToData(reader); @@ -248,51 +248,93 @@ public sealed class CharaDataFileHandler : IDisposable } internal async Task SaveCharaFileAsync(string description, string filePath) + { + var createPlayerDataStopwatch = System.Diagnostics.Stopwatch.StartNew(); + var data = await CreatePlayerData().ConfigureAwait(false); + createPlayerDataStopwatch.Stop(); + _logger.LogInformation("CreatePlayerData took {elapsed}ms", createPlayerDataStopwatch.ElapsedMilliseconds); + + if (data == null) return; + + await Task.Run(async () => await SaveCharaFileAsyncInternal(description, filePath, data).ConfigureAwait(false)).ConfigureAwait(false); + } + + private async Task SaveCharaFileAsyncInternal(string description, string filePath, CharacterData data) { var tempFilePath = filePath + ".tmp"; + var overallStopwatch = System.Diagnostics.Stopwatch.StartNew(); try { - var data = await CreatePlayerData().ConfigureAwait(false); - if (data == null) return; - var lightlessCharaFileData = _lightlessCharaFileDataFactory.Create(description, data); LightlessCharaFileHeader output = new(LightlessCharaFileHeader.CurrentVersion, lightlessCharaFileData); - using var fs = new FileStream(tempFilePath, FileMode.Create, FileAccess.ReadWrite, FileShare.None); + using var fs = new FileStream(tempFilePath, FileMode.Create, FileAccess.ReadWrite, FileShare.None, bufferSize: 65536, useAsync: false); using var lz4 = new LZ4Stream(fs, LZ4StreamMode.Compress, LZ4StreamFlags.HighCompression); using var writer = new BinaryWriter(lz4); output.WriteToStream(writer); + int fileIndex = 0; + long totalBytesWritten = 0; + foreach (var item in output.CharaFileData.Files) { + fileIndex++; + var fileStopwatch = System.Diagnostics.Stopwatch.StartNew(); + var file = _fileCacheManager.GetFileCacheByHash(item.Hash)!; - _logger.LogDebug("Saving to MCDF: {hash}:{file}", item.Hash, file.ResolvedFilepath); + _logger.LogDebug("Saving to MCDF [{fileNum}/{totalFiles}]: {hash}:{file}", fileIndex, output.CharaFileData.Files.Count, item.Hash, file.ResolvedFilepath); _logger.LogDebug("\tAssociated GamePaths:"); foreach (var path in item.GamePaths) { _logger.LogDebug("\t{path}", path); } - var fsRead = File.OpenRead(file.ResolvedFilepath); - await using (fsRead.ConfigureAwait(false)) + using var fsRead = File.OpenRead(file.ResolvedFilepath); + using var br = new BinaryReader(fsRead); + byte[] buffer = new byte[item.Length]; + int bytesRead = br.Read(buffer, 0, item.Length); + + if (bytesRead != item.Length) { - using var br = new BinaryReader(fsRead); - byte[] buffer = new byte[item.Length]; - br.Read(buffer, 0, item.Length); - writer.Write(buffer); + _logger.LogWarning("Expected to read {expected} bytes but got {actual} bytes from {file}", item.Length, bytesRead, file.ResolvedFilepath); } + + writer.Write(buffer); + totalBytesWritten += bytesRead; + + fileStopwatch.Stop(); + _logger.LogDebug("Wrote file [{fileNum}/{totalFiles}] in {elapsed}ms ({sizeKb}kb)", fileIndex, output.CharaFileData.Files.Count, fileStopwatch.ElapsedMilliseconds, item.Length / 1024); } + + var flushStopwatch = System.Diagnostics.Stopwatch.StartNew(); writer.Flush(); - await lz4.FlushAsync().ConfigureAwait(false); - await fs.FlushAsync().ConfigureAwait(false); + lz4.Flush(); + fs.Flush(); fs.Close(); + flushStopwatch.Stop(); + _logger.LogInformation("Flush operations took {elapsed}ms", flushStopwatch.ElapsedMilliseconds); + + var moveStopwatch = System.Diagnostics.Stopwatch.StartNew(); File.Move(tempFilePath, filePath, true); + moveStopwatch.Stop(); + _logger.LogInformation("File move took {elapsed}ms", moveStopwatch.ElapsedMilliseconds); + + overallStopwatch.Stop(); + _logger.LogInformation("SaveCharaFileAsync completed successfully in {elapsed}ms. Total bytes written: {totalBytes}mb", overallStopwatch.ElapsedMilliseconds, totalBytesWritten / (1024 * 1024)); } catch (Exception ex) { - _logger.LogError(ex, "Failure Saving Lightless Chara File, deleting output"); - File.Delete(tempFilePath); + overallStopwatch.Stop(); + _logger.LogError(ex, "Failure Saving Lightless Chara File after {elapsed}ms, deleting output", overallStopwatch.ElapsedMilliseconds); + try + { + File.Delete(tempFilePath); + } + catch (Exception deleteEx) + { + _logger.LogError(deleteEx, "Failed to delete temporary file {file}", tempFilePath); + } } }