My web service product ShufflePoint has a metered billing characteristic. In order to do the metering, every time a customer runs a query some information is logged to a SQL database. In a recent performance audit, I observed that this logging was taking several hundred milliseconds to perform. That represented about 25% of the time to process a request.
The current logging
The SQL update was being done with pretty vanilla .NET logic. It is shown below. As you see, a stored procedure is being invoked to perform the update. I did not see any optimization opportunities here. In the database schema there are no relationships or indexes - it is just an isolated logging table. My best bet, I thought, would be to buffer these single row inserts and perform a period batch insert.
using (SqlConnection conn = new SqlConnection(ms_aqlLoggerConnStr)) {
conn.Open();
using (SqlCommand cmd = new SqlCommand("AqlLogger_LogQuery", conn)) {
cmd.CommandType = CommandType.StoredProcedure;
SqlParameter input1 = cmd.Parameters.Add("@user", SqlDbType.UniqueIdentifier);
input1.Direction = ParameterDirection.Input;
input1.Value = new Guid(m_UserId);
SqlParameter input2 = cmd.Parameters.Add("@datasource",SqlDbType.NVarChar, 10);
input2.Direction = ParameterDirection.Input;
input2.Value = dataSource;
SqlParameter input3 = cmd.Parameters.Add("@profileid", SqlDbType.Int);
input3.Direction = ParameterDirection.Input;
input3.Value = profileId;
SqlParameter input4 = cmd.Parameters.Add("@web", SqlDbType.NVarChar, 256);
input4.Direction = ParameterDirection.Input;
input4.Value = webId;
SqlParameter input5 = cmd.Parameters.Add("@acct", SqlDbType.NVarChar, 256);
input5.Direction = ParameterDirection.Input;
input5.Value = accountId;
SqlParameter input6 = cmd.Parameters.Add("@runtime", SqlDbType.Int);
input6.Direction = ParameterDirection.Input;
input6.Value = totaltime;
SqlParameter input7 = cmd.Parameters.Add("@cellcount", SqlDbType.Int);
input7.Direction = ParameterDirection.Input;
input7.Value = cellcount;
cmd.ExecuteNonQuery();
}
}
Researching an alternative
In Googling on this topic, I came upon this article by Ted Spence. It showed a nice pattern for batch inserts. The question I then had was where and when to perform the batch insert. I could have created a class with an Insert method and which internally would buffer the records and then do a batch insert when the record count exceeded a specified threshold. Instead, I thought I'd try putting this logic into global.asax.
Changes to the database
Following the Ted Spence article, I first created a type in SQL Server:
CREATE TYPE AqlLoggerType AS TABLE ( [UserID] [uniqueidentifier] NOT NULL, [DataSource] [nvarchar](3) NOT NULL, [ProfileID] [int] NOT NULL, [WebProperty] [nvarchar](256) NOT NULL, [GaAccount] [nvarchar](256) NOT NULL, [Runtime] [int] NOT NULL, [CellCount] [int] NOT NULL, [QueryDate] [smalldatetime] NOT NULL DEFAULT (getdate()) )
The type reflects the record to be inserted. The other change was the addition of a stored procedure which performs the batch insert. It takes a single parameter of AqlLoggerType which contains the buffered records which are to be inserted.
CREATE PROCEDURE [dbo].[AqlLogger_LogQuery_Batch]
(
@logtable AqlLoggerType READONLY
)
AS
BEGIN
SET XACT_ABORT ON;
SET NOCOUNT ON;
INSERT INTO AqlLogger
(UserID, Datasource, ProfileID, WebProperty, GaAccount, Runtime, CellCount, QueryDate)
SELECT
UserID, Datasource, ProfileID, WebProperty, GaAccount, Runtime, CellCount, QueryDate
FROM
@logtable
END;
Global.asax modifications
The changes to Global.asax are shown below. A static variable of type DataTable was added to the class. In Application_Start() a DataTable is instantiated and the columns are added. Then in Application_End(), the storted procedure AqlLogger_LogQuery_Batch is invoked, passing in the DataTable.
public class Global : System.Web.HttpApplication
{
...
public static DataTable AqlBatchTable;
...
protected void Application_Start(Object sender, EventArgs e)
{
...
// initialize the batch update table
InitAqlBatchTable();
}
public static void InitAqlBatchTable()
{
// setup a datatable for batch AQL logging
DataTable AqlBatchTable = new DataTable();
AqlBatchTable.Columns.Add(new DataColumn("UserID", typeof(Guid)));
AqlBatchTable.Columns.Add(new DataColumn("DataSource", typeof(string)));
AqlBatchTable.Columns.Add(new DataColumn("ProfileID", typeof(int)));
AqlBatchTable.Columns.Add(new DataColumn("WebProperty", typeof(string)));
AqlBatchTable.Columns.Add(new DataColumn("GaAccount", typeof(string)));
AqlBatchTable.Columns.Add(new DataColumn("Runtime", typeof(int)));
AqlBatchTable.Columns.Add(new DataColumn("CellCount", typeof(int)));
AqlBatchTable.Columns.Add(new DataColumn("QueryDate", typeof(DateTime)));
}
...
protected void Application_End(Object sender, EventArgs e)
{
try {
Configuration rootWebConfig = WebConfigurationManager.OpenWebConfiguration("~");
ConnectionStringSettings css = rootWebConfig.ConnectionStrings.ConnectionStrings["LocalSqlServer"];
using (SqlConnection conn = new SqlConnection(css.ConnectionString)) {
conn.Open();
using (SqlCommand cmd = new SqlCommand("AqlLogger_LogQuery_Batch", conn)) {
cmd.CommandType = CommandType.StoredProcedure;
SqlParameter param = new SqlParameter("@logtable", SqlDbType.Structured);
param.Value = AqlBatchTable;
cmd.Parameters.Add(param);
cmd.ExecuteNonQuery();
}
}
} catch ...
}
}
Logging code modifications
A new logging method was added which inserts a single row of tracking information to reflect the metered tracking of the users action.
private int mLogUserQueryBatch(string dataSource, int profileId, string webId,
string accountId, int totaltime, int cellcount, DateTime dt)
{
int retval = 0;
if (!ms_bLogAql) {
return retval;
}
log.Debug("in mLogUserQueryBatch");
try {
Global.AqlBatchTable.Rows.Add(new object[] {
new Guid(m_UserId),
dataSource,
profileId,
webId,
accountId,
totaltime,
cellcount,
dt
});
} catch (Exception ex) {
log.ErrorFormat("LogUserQueryBatch failed: {0}",ex.ToString());
}
return retval;
}
Results
The call to mLogUserQueryBatch() only takes a few tens of milliseconds compared to a few hundreds of milliseconds - about a ten-fold improvement. I think this was a performance improvement worth making. My only concern is that I am depending upon Application_End() being called, and on the batch update succeeding. If this process fails, then I'll have lost that batch of customer activity metering.
