We have a ported application from G120 to SCM20260N that has issues in “some” cases after “some” time. It is blocking going into production with the product. We were able to track this down to the logger that generates an exception.
Code bellow is a 100% failure simulation.
The amount of files it generates “before” the exception in 10 test cycles:
Run 1 failed in file number 13
Run 2 failed in file number 55
Run 3 failed in file number 81
Run 4 failed in file number 108
Run 5 failed in file number 79
Run 6 failed in file number 104
Run 7 failed in file number 52
Run 8 failed in file number 33
Run 9 failed in file number 103
Run 10 failed in file number 35
The exception is:
#### Exception System.InvalidOperationException - CLR_E_INVALID_OPERATION (3) ####
#### Message:
#### GHIElectronics.TinyCLR.IO.FileSystem+NativeFileStream::Write [IP: 0000] ####
#### System.IO.FileStream::Write [IP: 0041] ####
#### System.IO.StreamWriter::Flush [IP: 0021] ####
#### Test_Logger_code.Startup::MAIN_thread [IP: 0028] ####
An exception of type ‘System.InvalidOperationException’ occurred in GHIElectronics.TinyCLR.IO.dll and wasn’t handled before a managed/native boundary
We are running 2.2.0.4200
The test code to reproduce the exception:
using System.IO;
using System.Threading;
using System.Diagnostics;
using GHIElectronics.TinyCLR.IO;
using GHIElectronics.TinyCLR.Devices.Storage;
namespace Test_Logger_code
{
public class Startup
{
public static StorageController sd;
public static StreamWriter LogFile;
public static IDriveProvider drive;
public static DirectoryInfo directory;
public static FileInfo[] files;
public static Thread MAINT;
public static Thread FLUSH;
public static uint FileCounter = 0;
public static uint LineCounter = 0;
static void Main()
{
sd = StorageController.FromName(GHIElectronics.TinyCLR.Pins.SC20260.StorageController.SdCard);
drive = FileSystem.Mount(sd.Hdc);
directory = new DirectoryInfo(drive.Name);
files = directory.GetFiles();
CreateNewLogFile();
MAINT = new Thread(MAIN_thread)
{
Priority = ThreadPriority.Normal
};
FLUSH = new Thread(FLUSH_thread)
{
Priority = ThreadPriority.Normal
};
FLUSH.Start();
MAINT.Start();
Thread.Sleep(Timeout.Infinite);
}
public static void MAIN_thread()
{
while (true)
{
LineCounter++;
LogFile.WriteLine("Just a dummy line..." + LineCounter.ToString() + " and some extra data to mach a bit closer to a MFC log file line...");
LogFile.Flush();
if (LineCounter == 1000)
{
// Close current file and create a new one
CreateNewLogFile();
// Reset the line counter
LineCounter = 0;
}
Thread.Sleep(10);
}
}
public static void FLUSH_thread()
{
while (true)
{
FileSystem.Flush(sd.Hdc);
Thread.Sleep(5000);
}
}
public static void CreateNewLogFile()
{
// Filecounter + 1
FileCounter++;
// Show some activity
Debug.WriteLine("File number " + FileCounter.ToString() + " created");
// Not for the first file
if (LogFile != null)
{
// Close the file
LogFile.Close();
LogFile.Dispose();
}
// Flush whatever is left in buffers
FileSystem.Flush(sd.Hdc);
// Create new log file
LogFile = new StreamWriter($@"{drive.Name}Data" + FileCounter.ToString() + ".log", true);
}
}
}
Is there a work around for this kind of issue or is a firmware update required?
In the complete application there is a lock used, but i will to add this to the test code to see if it helps.
There is no issue with the 2 hreads for writing / flushing, this has been running for day’s.
But it started after i added the new file generating after 1000 lines.
Thx for the tip, i will post the result.
using System;
using System.IO;
using System.Threading;
using System.Diagnostics;
using GHIElectronics.TinyCLR.IO;
using GHIElectronics.TinyCLR.Devices.Storage;
namespace Test_Logger_code
{
public class Startup
{
public static StorageController sd;
public static StreamWriter LogFile;
public static IDriveProvider drive;
public static DirectoryInfo directory;
public static FileInfo[] files;
public static Thread MAINT;
public static Thread FLUSH;
public static object LogFile_Lock = new Object();
public static uint FileCounter = 0;
public static uint LineCounter = 0;
static void Main()
{
sd = StorageController.FromName(GHIElectronics.TinyCLR.Pins.SC20260.StorageController.SdCard);
drive = FileSystem.Mount(sd.Hdc);
directory = new DirectoryInfo(drive.Name);
files = directory.GetFiles();
CreateNewLogFile();
MAINT = new Thread(MAIN_thread)
{
Priority = ThreadPriority.Normal
};
FLUSH = new Thread(FLUSH_thread)
{
Priority = ThreadPriority.Normal
};
FLUSH.Start();
MAINT.Start();
Thread.Sleep(Timeout.Infinite);
}
public static void MAIN_thread()
{
while (true)
{
lock (LogFile_Lock)
{
LineCounter++;
LogFile.WriteLine("Just a dummy line..." + LineCounter.ToString() + " and some extra data to mach a bit closer to a MFC log file line...");
LogFile.Flush();
if (LineCounter == 1000)
{
// Close current file and create a new one
CreateNewLogFile();
// Reset the line counter
LineCounter = 0;
}
}
Thread.Sleep(10);
}
}
public static void FLUSH_thread()
{
while (true)
{
lock (LogFile_Lock)
{
FileSystem.Flush(sd.Hdc);
}
Thread.Sleep(5000);
}
}
public static void CreateNewLogFile()
{
// Filecounter + 1
FileCounter++;
// Show some activity
Debug.WriteLine("File number " + FileCounter.ToString() + " created");
// Not for the first file
if (LogFile != null)
{
// Close the file
LogFile.Close();
LogFile.Dispose();
}
// Flush whatever is left in buffers
FileSystem.Flush(sd.Hdc);
// Create new log file
LogFile = new StreamWriter($@"{drive.Name}Data" + FileCounter.ToString() + ".log", true);
}
}
}
It’s a custom board where we replaced G120 with 20260, hardware should be ok, running in the field for years with NETMF and we checked the possible issues. I will try to run the same code on a DEV board and post the results.
For the first test on the DEV board we changed the sleep value in MAINT from 10 to 50ms
Test was running for 15 hours, generated 1200+ files and no issues.
We changed the sleep value in MAINT back to 10ms and started the test gain.
Run 1 exception was raised after 97 files.
Run 2 exception was raised after 25 files
Run 3 exception was raised after 30 files
Run 4 exception was raised after 231 files
Run 5 is still running and is on 590 files as we write this.
We also deployed the test code with the 50ms sleep to the custom board and this also still running, 303 files created as we write this.
We keep test running for know and see if with some software throttling we can get this stable whithout changing the hardware.
Change sleep 10 to 50ms just make harder to reproduce.
Below is proper way (I think), and use sleep (0), generate 2000+ files in shortly.
Although limited of FAT32 is much higher than 2000+ file in a folder, but when I test on PC, it takes much longer to access the SD if 2000+ files in root folder. It may cause an issue on SITCORE because timeout is 5 seconds. I think every 2000 files or less, you should split into a different folder.
Below is what I recommend to test, if you have time, look at GHI added and GHI remove to see how we changed.
static object objectlock = new object();
public static void MAIN_thread()
{
while (true)
{
LineCounter++;
lock (objectlock)
{
LogFile.WriteLine("Just a dummy line..." + LineCounter.ToString() + " and some extra data to mach a bit closer to a MFC log file line...");
// LogFile.Flush(); GHI removed
if (LineCounter == 1000)
{
// Close current file and create a new one
LogFile.Flush(); //GHI added
CreateNewLogFile();
// Reset the line counter
LineCounter = 0;
}
}
Thread.Sleep(0);
}
}
public static void FLUSH_thread()
{
while (true)
{
lock (objectlock)
{
FileSystem.Flush(sd.Hdc);
}
Thread.Sleep(5000);
}
}
public static void CreateNewLogFile()
{
// Filecounter + 1
FileSystem.Flush(sd.Hdc); // GHI added: Flush everything befor close
FileCounter++;
// Show some activity
Debug.WriteLine("File number " + FileCounter.ToString() + " created");
// Not for the first file
if (LogFile != null)
{
// Close the file
LogFile.Close();
LogFile.Dispose();
}
///FileSystem.Flush(sd.Hdc); // GHI removed
// Create new log file
LogFile = new StreamWriter($@"{drive.Name}Data" + FileCounter.ToString() + ".log", true);
}
We actualy did that same software modification on the test code we did run last night on the custom hardware.
The result was exception free, generated 17.805 files over ± 15 hours.
We also had this without mofication running on the DEV board where we had 15.789 files generated. Also no exceptions (not sure why we had exceptions on DEV before, i did switch SD cards during the testing because the dev board had a different brand (SanDisk Ultra))
Moving the flush seems stable, we will apply this to the ported application and start a duration stress test that we keep running until next monday, if this passes then the problem is solved
The big number of files (15.000+) during these test on SD card was a issue when we tried to delete them (not for creating them so this is perfect). In the field this will be no issue because we delete the oldest files when we go above 200 files.
Before the test, make sure the SD is nice and clean (formatted). Sometime write/read failed randomly and when I insert the SD to PC, the PC asked for fixing problem, although I can read/write those files as well without select fixing. This is easy to happen when the application is running and we select stop VS debugger, or exception happened, and these test files are not closed in proper way. If you continue to test with this SD without format, the exception can be happened easily.
SITCore doesn’t have feature to warning the SD need to be fixed :)), so for accurate result, just format the SD every long test.
And, even no longer see the issue, we should handle the exception, add your code to recover data. We may don’t see exception at hour 15th, but can be 16th, not on this SD, but on other ones :)).
