Added debug logging

psyGamer · psyGamer · commit ea0a3918185d · 2023-09-29T15:36:29.000+02:00
diff --git a/Source/AudioCapture.cs b/Source/AudioCapture.cs
@@ -1,3 +1,4 @@
+using Celeste.Mod.TASRecorder.Util;
 using FMOD;
 using System;
 using System.Runtime.InteropServices;
@@ -83,6 +84,7 @@ private static unsafe RESULT CaptureCallback(ref DSP_STATE dspState, IntPtr inBu
                 }
             }
         }
+        Log.Debug($"Capturing {samples} samples");
 
         // Block until the management thread allows capturing more (also blocks the main FMOD thread which is good, since it avoid artifacts)
         while (TASRecorderModule.Recording && !allowCapture) { }
@@ -106,6 +108,7 @@ private static unsafe RESULT CaptureCallback(ref DSP_STATE dspState, IntPtr inBu
     }
 
     private static void CaptureThread() {
+        Log.Debug("Starting audio capture thread");
         totalRecodedSamplesError = 0;
         batchesToIgnore = 5;
 
@@ -117,18 +120,22 @@ private static void CaptureThread() {
 
             // Skip a frame to let the video catch up again
             if (totalRecodedSamplesError >= targetRecordedSamples) {
+                Log.Debug("Skipping audio frame to allow video to catch up");
                 totalRecodedSamplesError -= targetRecordedSamples;
                 continue;
             }
 
             // Capture at least a frame of data on the FMOD/DSP thread
+            Log.Debug("Starting audio capture");
             allowCapture = true;
             while (runThread && recordedSamples < targetRecordedSamples) { }
             allowCapture = false;
+            Log.Debug("Stopping audio capture");
 
             // Accumulate the data overhead
             totalRecodedSamplesError += recordedSamples - targetRecordedSamples;
             recordedSamples = 0;
         }
+        Log.Debug("Stopped audio capture thread");
     }
 }
diff --git a/Source/Encoder.cs b/Source/Encoder.cs
@@ -131,6 +131,7 @@ public void RefreshSettings() {
     }
 
     public void PrepareVideo(int width, int height) {
+        Log.Debug($"Preparing video at {width}x{height}...");
         ref var outStream = ref VideoStream;
         var ctx = outStream.CodecCtx;
 
@@ -151,8 +152,10 @@ public void PrepareVideo(int width, int height) {
         }
 
         VideoData = outStream.InFrame->data[0];
+        Log.Debug("Prepared video");
     }
     public void PrepareAudio(uint channelCount, uint sampleCount) {
+        Log.Debug($"Preparing audio at {channelCount} channels and {sampleCount} samples...");
         AudioDataSize = Math.Max(channelCount, AUDIO_CHANNEL_COUNT) * sampleCount * (uint) Marshal.SizeOf<float>();
         AudioDataSamples = sampleCount;
         AudioDataChannels = channelCount;
@@ -161,9 +164,11 @@ public void PrepareAudio(uint channelCount, uint sampleCount) {
             AudioDataBufferSize = AudioDataSize * 2; // Avoid having to reallocate soon
             AudioData = (byte*) NativeMemory.Realloc(AudioData, AudioDataBufferSize);
         }
+        Log.Debug("Prepared audio");
     }
 
     public void FinishVideo() {
+        Log.Debug("Finishing video...");
         ref var outStream = ref VideoStream;
         var ctx = outStream.CodecCtx;
 
@@ -177,6 +182,7 @@ public void FinishVideo() {
         outStream.OutFrame->pts = outStream.VideoPTS;
 
         WriteFrame(ref outStream, outStream.OutFrame);
+        Log.Debug("Finished video");
     }
     public void FinishAudio() {
         ref var outStream = ref AudioStream;
@@ -211,6 +217,7 @@ public void FinishAudio() {
                 WriteFrame(ref outStream, outStream.OutFrame);
             }
         }
+        Log.Debug("Finished audio");
     }
 
     private void AddStream(AVCodec* codec, ref OutputStream outStream, AVCodecID codecID) {
diff --git a/Source/FFmpegLoader.cs b/Source/FFmpegLoader.cs
@@ -132,13 +132,24 @@ private static Task Validate() => Task.Run(() => {
             // First, check for system libraries.
             Log.Debug("Attempting to load system FFmpeg libraries...");
             try {
+                Log.Debug($"Loading {GetOSLibraryName("avutil")}");
                 AvutilLibrary = NativeLibrary.Load(GetOSLibraryName("avutil"));
+                Log.Debug($"Loading {GetOSLibraryName("avformat")}");
                 AvformatLibrary = NativeLibrary.Load(GetOSLibraryName("avformat"));
+                Log.Debug($"Loading {GetOSLibraryName("avcodec")}");
                 AvcodecLibrary = NativeLibrary.Load(GetOSLibraryName("avcodec"));
+                Log.Debug($"Loading {GetOSLibraryName("swresample")}");
                 SwresampleLibrary = NativeLibrary.Load(GetOSLibraryName("swresample"));
+                Log.Debug($"Loading {GetOSLibraryName("swscale")}");
                 SwscaleLibrary = NativeLibrary.Load(GetOSLibraryName("swscale"));
 
-                Log.Debug("Successfully loaded system FFmpeg libraries.");
+                Log.Debug($"avutil: {GetVersionString(avutil_version())}");
+                Log.Debug($"avformat: {GetVersionString(avformat_version())}");
+                Log.Debug($"avcodec: {GetVersionString(avcodec_version())}");
+                Log.Debug($"swresample: {GetVersionString(swresample_version())}");
+                Log.Debug($"swscale: {GetVersionString(swscale_version())}");
+
+                Log.Info("Successfully loaded system FFmpeg libraries.");
 
                 // Libraries are installed on the system, delete the Cache if it exists.
                 if (File.Exists(ChecksumPath))
@@ -188,11 +199,11 @@ private static Task Validate() => Task.Run(() => {
             _validated = true;
             _installed = true;
             try {
-                Log.Info($"avutil: {GetVersionString(avutil_version())}");
-                Log.Info($"avformat: {GetVersionString(avformat_version())}");
-                Log.Info($"avcodec: {GetVersionString(avcodec_version())}");
-                Log.Info($"swresample: {GetVersionString(swresample_version())}");
-                Log.Info($"swscale: {GetVersionString(swscale_version())}");
+                Log.Debug($"avutil: {GetVersionString(avutil_version())}");
+                Log.Debug($"avformat: {GetVersionString(avformat_version())}");
+                Log.Debug($"avcodec: {GetVersionString(avcodec_version())}");
+                Log.Debug($"swresample: {GetVersionString(swresample_version())}");
+                Log.Debug($"swscale: {GetVersionString(swscale_version())}");
             } catch (Exception ex) {
                 Log.Error("Failed linking against FFmpeg libraries! Starting without FFmpeg libraries.");
                 Log.Exception(ex);
@@ -312,15 +323,15 @@ private static bool LoadLibrariesFromCache() {
         // However if we are loading from Cache, there is no system library.
         Log.Debug("Trying to load libraries from cache...");
         try {
-            Log.Verbose($"Loading {Path.Combine(InstallPath, AvutilName)}");
+            Log.Debug($"Loading {Path.Combine(InstallPath, AvutilName)}");
             AvutilLibrary = NativeLibrary.Load(Path.Combine(InstallPath, AvutilName));
-            Log.Verbose($"Loading {Path.Combine(InstallPath, SwresampleName)}");
+            Log.Debug($"Loading {Path.Combine(InstallPath, SwresampleName)}");
             SwresampleLibrary = NativeLibrary.Load(Path.Combine(InstallPath, SwresampleName)); // Depends on: avutil
-            Log.Verbose($"Loading {Path.Combine(InstallPath, SwscaleName)}");
+            Log.Debug($"Loading {Path.Combine(InstallPath, SwscaleName)}");
             SwscaleLibrary = NativeLibrary.Load(Path.Combine(InstallPath, SwscaleName));       // Depends on: avutil
-            Log.Verbose($"Loading {Path.Combine(InstallPath, AvcodecName)}");
+            Log.Debug($"Loading {Path.Combine(InstallPath, AvcodecName)}");
             AvcodecLibrary = NativeLibrary.Load(Path.Combine(InstallPath, AvcodecName));       // Depends on: avutil, swresample
-            Log.Verbose($"Loading {Path.Combine(InstallPath, AvformatName)}");
+            Log.Debug($"Loading {Path.Combine(InstallPath, AvformatName)}");
             AvformatLibrary = NativeLibrary.Load(Path.Combine(InstallPath, AvformatName));     // Depends on: avutil, avcodec, swresample
 
             return true;
diff --git a/Source/VideoCapture.cs b/Source/VideoCapture.cs
@@ -1,3 +1,4 @@
+using Celeste.Mod.TASRecorder.Util;
 using Microsoft.Xna.Framework;
 using Microsoft.Xna.Framework.Graphics;
 using Monocle;
@@ -58,6 +59,7 @@ internal static void Unload() {
     private static bool updateHappened;
 
     private static unsafe void CaptureFrame() {
+        Log.Debug("Starting frame capture");
         int width = captureTarget.Width;
         int height = captureTarget.Height;
 
@@ -80,6 +82,7 @@ private static unsafe void CaptureFrame() {
             }
         }
         TASRecorderModule.Encoder.FinishVideo();
+        Log.Debug("Successfully captured frame");
     }
 
     // Taken from Engine.UpdateView(), but without depending on presentation parameters

Original file line number	Diff line number	Diff line change
`@@ -1,3 +1,4 @@`
	`1`	`+using Celeste.Mod.TASRecorder.Util;`
`1`	`2`	`using FMOD;`
`2`	`3`	`using System;`
`3`	`4`	`using System.Runtime.InteropServices;`
`@@ -83,6 +84,7 @@ private static unsafe RESULT CaptureCallback(ref DSP_STATE dspState, IntPtr inBu`
`83`	`84`	`}`
`84`	`85`	`}`
`85`	`86`	`}`
	`87`	`+ Log.Debug($"Capturing {samples} samples");`
`86`	`88`
`87`	`89`	`// Block until the management thread allows capturing more (also blocks the main FMOD thread which is good, since it avoid artifacts)`
`88`	`90`	`while (TASRecorderModule.Recording && !allowCapture) { }`
`@@ -106,6 +108,7 @@ private static unsafe RESULT CaptureCallback(ref DSP_STATE dspState, IntPtr inBu`
`106`	`108`	`}`
`107`	`109`
`108`	`110`	`private static void CaptureThread() {`
	`111`	`+ Log.Debug("Starting audio capture thread");`
`109`	`112`	`totalRecodedSamplesError = 0;`
`110`	`113`	`batchesToIgnore = 5;`
`111`	`114`
`@@ -117,18 +120,22 @@ private static void CaptureThread() {`
`117`	`120`
`118`	`121`	`// Skip a frame to let the video catch up again`
`119`	`122`	`if (totalRecodedSamplesError >= targetRecordedSamples) {`
	`123`	`+ Log.Debug("Skipping audio frame to allow video to catch up");`
`120`	`124`	`totalRecodedSamplesError -= targetRecordedSamples;`
`121`	`125`	`continue;`
`122`	`126`	`}`
`123`	`127`
`124`	`128`	`// Capture at least a frame of data on the FMOD/DSP thread`
	`129`	`+ Log.Debug("Starting audio capture");`
`125`	`130`	`allowCapture = true;`
`126`	`131`	`while (runThread && recordedSamples < targetRecordedSamples) { }`
`127`	`132`	`allowCapture = false;`
	`133`	`+ Log.Debug("Stopping audio capture");`
`128`	`134`
`129`	`135`	`// Accumulate the data overhead`
`130`	`136`	`totalRecodedSamplesError += recordedSamples - targetRecordedSamples;`
`131`	`137`	`recordedSamples = 0;`
`132`	`138`	`}`
	`139`	`+ Log.Debug("Stopped audio capture thread");`
`133`	`140`	`}`
`134`	`141`	`}`
Original file line number	Diff line number	Diff line change
`@@ -131,6 +131,7 @@ public void RefreshSettings() {`
`131`	`131`	`}`
`132`	`132`
`133`	`133`	`public void PrepareVideo(int width, int height) {`
	`134`	`+ Log.Debug($"Preparing video at {width}x{height}...");`
`134`	`135`	`ref var outStream = ref VideoStream;`
`135`	`136`	`var ctx = outStream.CodecCtx;`
`136`	`137`
`@@ -151,8 +152,10 @@ public void PrepareVideo(int width, int height) {`
`151`	`152`	`}`
`152`	`153`
`153`	`154`	`VideoData = outStream.InFrame->data[0];`
	`155`	`+ Log.Debug("Prepared video");`
`154`	`156`	`}`
`155`	`157`	`public void PrepareAudio(uint channelCount, uint sampleCount) {`
	`158`	`+ Log.Debug($"Preparing audio at {channelCount} channels and {sampleCount} samples...");`
`156`	`159`	`AudioDataSize = Math.Max(channelCount, AUDIO_CHANNEL_COUNT) * sampleCount * (uint) Marshal.SizeOf<float>();`
`157`	`160`	`AudioDataSamples = sampleCount;`
`158`	`161`	`AudioDataChannels = channelCount;`
`@@ -161,9 +164,11 @@ public void PrepareAudio(uint channelCount, uint sampleCount) {`
`161`	`164`	`AudioDataBufferSize = AudioDataSize * 2; // Avoid having to reallocate soon`
`162`	`165`	`AudioData = (byte*) NativeMemory.Realloc(AudioData, AudioDataBufferSize);`
`163`	`166`	`}`
	`167`	`+ Log.Debug("Prepared audio");`
`164`	`168`	`}`
`165`	`169`
`166`	`170`	`public void FinishVideo() {`
	`171`	`+ Log.Debug("Finishing video...");`
`167`	`172`	`ref var outStream = ref VideoStream;`
`168`	`173`	`var ctx = outStream.CodecCtx;`
`169`	`174`
`@@ -177,6 +182,7 @@ public void FinishVideo() {`
`177`	`182`	`outStream.OutFrame->pts = outStream.VideoPTS;`
`178`	`183`
`179`	`184`	`WriteFrame(ref outStream, outStream.OutFrame);`
	`185`	`+ Log.Debug("Finished video");`
`180`	`186`	`}`
`181`	`187`	`public void FinishAudio() {`
`182`	`188`	`ref var outStream = ref AudioStream;`
`@@ -211,6 +217,7 @@ public void FinishAudio() {`
`211`	`217`	`WriteFrame(ref outStream, outStream.OutFrame);`
`212`	`218`	`}`
`213`	`219`	`}`
	`220`	`+ Log.Debug("Finished audio");`
`214`	`221`	`}`
`215`	`222`
`216`	`223`	`private void AddStream(AVCodec* codec, ref OutputStream outStream, AVCodecID codecID) {`
Original file line number	Diff line number	Diff line change
`@@ -1,3 +1,4 @@`
	`1`	`+using Celeste.Mod.TASRecorder.Util;`
`1`	`2`	`using Microsoft.Xna.Framework;`
`2`	`3`	`using Microsoft.Xna.Framework.Graphics;`
`3`	`4`	`using Monocle;`
`@@ -58,6 +59,7 @@ internal static void Unload() {`
`58`	`59`	`private static bool updateHappened;`
`59`	`60`
`60`	`61`	`private static unsafe void CaptureFrame() {`
	`62`	`+ Log.Debug("Starting frame capture");`
`61`	`63`	`int width = captureTarget.Width;`
`62`	`64`	`int height = captureTarget.Height;`
`63`	`65`
`@@ -80,6 +82,7 @@ private static unsafe void CaptureFrame() {`
`80`	`82`	`}`
`81`	`83`	`}`
`82`	`84`	`TASRecorderModule.Encoder.FinishVideo();`
	`85`	`+ Log.Debug("Successfully captured frame");`
`83`	`86`	`}`
`84`	`87`
`85`	`88`	`// Taken from Engine.UpdateView(), but without depending on presentation parameters`