Slow opening SQLite connection in C# app using System.Data.SQLite

Question

Edit 3:

I guess my issue is resolved for the moment... I changed both my service and test app to run as the SYSTEM account instead of the NetworkService account. It remains to be seen if the benefits of changing the user account will persist, or if it will only be temporary.

Original Question:

I've noticed that my small 224kB SQLite DB is very slow to open in my C# application, taking anywhere from some small number of ms, to 1.5 seconds or more. Below is my code, with all the extra debugging statements I've added this afternoon. I've narrowed it down to the call to cnn.Open(); as shown in the logs here:

2014-03-27 15:05:39,864 DEBUG - Creating SQLiteConnection...
2014-03-27 15:05:39,927 DEBUG - SQLiteConnection Created!
2014-03-27 15:05:39,927 DEBUG - SQLiteConnection Opening...
2014-03-27 15:05:41,627 DEBUG - SQLiteConnection Opened!
2014-03-27 15:05:41,627 DEBUG - SQLiteCommand Creating...
2014-03-27 15:05:41,627 DEBUG - SQLiteCommand Created!
2014-03-27 15:05:41,627 DEBUG - SQLiteCommand executing reader...
2014-03-27 15:05:41,658 DEBUG - SQLiteCommand executed reader!
2014-03-27 15:05:41,658 DEBUG - DataTable Loading...
2014-03-27 15:05:41,767 DEBUG - DataTable Loaded!

As you can see, in this instance it took 1.7 SECONDS to open the connection. I've tried repeating this, and cannot predict whether subsequent connections will open nearly immediately, or be delayed like this.

I've considered using some form of connection pooling, but is it worthwhile to pursue that for a single-instance single-threaded application? Right now, I'm creating an instance of my SQLiteDatabase class, and calling the below function for each of my queries.

public DataTable GetDataTable(string sql)
{
    DataTable dt = new DataTable();
    try
    {
        Logging.LogDebug("Creating SQLiteConnection...");
        using (SQLiteConnection cnn = new SQLiteConnection(dbConnection))
        {
            Logging.LogDebug("SQLiteConnection Created!");
            Logging.LogDebug("SQLiteConnection Opening...");
            cnn.Open();
            Logging.LogDebug("SQLiteConnection Opened!");
            Logging.LogDebug("SQLiteCommand Creating...");
            using (SQLiteCommand mycommand = new SQLiteCommand(cnn))
            {
                Logging.LogDebug("SQLiteCommand Created!");
                mycommand.CommandText = sql;
                Logging.LogDebug("SQLiteCommand executing reader...");
                using (SQLiteDataReader reader = mycommand.ExecuteReader())
                {
                    Logging.LogDebug("SQLiteCommand executed reader!");
                    Logging.LogDebug("DataTable Loading...");
                    dt.Load(reader);
                    Logging.LogDebug("DataTable Loaded!");
                    reader.Close();
                }
            }
            cnn.Close();
        }
    }
    catch (Exception e)
    {
        throw new Exception(e.Message);
    }
    return dt;
}

Edit:

Sure, dbConnection is the connection string, set by the following function. inputFile is just the string path of the filename to open.

public SqLiteDatabase(String inputFile)
{
    dbConnection = String.Format("Data Source={0}", inputFile);
}

And at this point, I think sql is irrelevant, as it's not making it to that point when the cnn.Open() stalls.

Edit 2:

Ok, I've done some more testing. Running the testing locally, it completes a 1000 iteration loop in ~5 seconds, for about 5ms per call to cnn.Open(). Running the test from the same windows installer that I did on my local PC, it completes in ~25 minutes, averaging 1468ms per call to cnn.Open().

I made a small test program that only calls the TestOpenConn() function from the service program (same exact code that is running in the Windows service), running against a copy of the file located in a test directory. Running this on the server or my local PC results in acceptable performance (1.95ms per call on the server, 4ms per call on my local PC):

namespace EGC_Timing_Test
{
    class Program
    {
        static void Main(string[] args)
        {
            Logging.Init("log4net.xml", "test.log");
            var db = new SqLiteDatabase("config.sqlite");
            db.TestOpenConn();
        }
    }
}

Here's the test function:

public void TestOpenConn()
{
    // TODO: Remove this after testing loop of opening / closing SQLite DB repeatedly:
    const int iterations = 1000;
    Logging.LogDebug(String.Format("Running TestOpenConn for {0} opens...", iterations));
    var startTime = DateTime.Now;
    for (var i = 0; i < iterations; i++)
    {
        using (SQLiteConnection cnn = new SQLiteConnection(dbConnection))
        {
            Logging.LogDebug(String.Format("SQLiteConnection Opening, iteration {0} of {1}...", i, iterations));
            var startTimeInner = DateTime.Now;
            cnn.Open();
            var endTimeInner = DateTime.Now;
            var diffTimeInner = endTimeInner - startTimeInner;
            Logging.LogDebug(String.Format("SQLiteConnection Opened in {0}ms!", diffTimeInner.TotalMilliseconds));
            cnn.Close();
        }
    }
    var endTime = DateTime.Now;
    var diffTime = endTime - startTime;
    Logging.LogDebug(String.Format("Done running TestOpenConn for {0} opens!", iterations));
    Logging.LogInfo(String.Format("{0} iterations total:\t{1}", iterations, diffTime));
    Logging.LogInfo(String.Format("{0} iterations average:\t{1}ms", iterations, diffTime.TotalMilliseconds/iterations));
}

Answer 1

I guess my issue is resolved for the moment... I changed both my service and test app to run as the SYSTEM account instead of the NetworkService account. It remains to be seen if the benefits of changing the user account will persist, or if it will only be temporary.

Answer 2

I'm assuming you're using the open source System.Data.SQLite library.

If that's the case, it's easy to see through the Visual Studio Performance Profiler that the Open method of the SQLiteConnection class has some serious performance issues. Also, have a lookthrough the source code for this class here: https://system.data.sqlite.org/index.html/artifact/97648754af51ffd6

There's an awful lot of disk access being made to read XML configuration and Windows environment variable(s).

My suggestion is to try and call Open() as seldom as possible, and try and keep a reference to this open SQLiteConnection object around in memory. A performance ticket is raised with SQLite Forum

Answer 3

Having had the same problem, I was looking into this and it seems to be related to permissions on the file or it's parent folders, who created it, and/or how it was created. In my case, the SQLite database file was being created by a script run as a regular user, and then an IIS-hosted service would access the file under a different domain service account.

Every time the service opened a connection, it took over 1.5 seconds, but otherwise operated correctly (it could eventually access the file). A stand-alone program running as the regular user could open a connection to the same file in the same place in a few milliseconds.

Analysis of a procmon trace revealed that in the case of the service, we were getting several ACCESS DENIED logs on the file over the course of about 1.5 seconds, that were not present in the trace when running as the regular user.

Not sure what's going on there. The service worked fine and was able to eventually query the data in the file, albeit slowly.

When we made the service account the owner of the parent folder of the file, and gave him write permission, the ACCESS DENIED logs disappeared and the service operated at full speed.