DatabaseTarget - Removed logEvent-parameter from CreateDatabaseParameter

[snakefoot]

Update the new NLog 4.6 method CreateDatabaseParameter, so it is open for batching support.

[snakefoot]

Custom pre-release-build for those who wants to test performance (Just remove zip-extension):

NLog.4.6.0-PR3131.nupkg.zip

Updated PS3131-build available with improved DbCommand caching:

NLog.4.6.0-PS3131.nupkg.zip

[304NotModified]

this is another change than the PR title suggests?

[snakefoot]

Nope just me moving code around to optimize the batching-logic (Single scope for the entire batch)

[304NotModified]

OK thanks!

[304NotModified]

Thanks! moved it to #3132, so we could easy integrate it into dev and master.

[snakefoot]

Could this become NLog 4.6, because this is actually a breaking change if NLog 4.6 is released (Removed LogEventInfo-parameter from CreateDatabaseParameter)

[snakefoot]

Also ready to separate PR that just includes the breaking change in CreateDatabaseParameter. Just to prepare for this PR.

[304NotModified]

please rebase on dev, thanks!

[snakefoot]

@304NotModified please rebase on dev, thanks!

Done

[D9001]

Custom pre-release-build for those who wants to test performance (Just remove zip-extension):

NLog.4.6.0-PR3131.nupkg.zip

2019-02-21 18:33:54.0713 Error DatabaseTarget(Name=wrapped_db): Error when writing to database. Exception: System.InvalidOperationException: SqlCommand.Prepare method requires all parameters to have a
n explicitly set type.
at System.Data.SqlClient.SqlParameter.Prepare(SqlCommand cmd)
at System.Data.SqlClient.SqlCommand.Prepare()
at NLog.Targets.DatabaseTarget.WriteEventToDatabase(IDbCommand command, LogEventInfo logEvent, Layout commandLayout, IList1 databaseParameterInfos, Boolean prepareDbCommand) at NLog.Targets.DatabaseTarget.Write(IList1 logEvents)

I received this error. I'm going home tonight and will see if I'm missing an attribute on the parameter nodes, but I've essentially mirrored your example + added my connection string.

[codecov]

Codecov Report

Merging #3131 into dev will increase coverage by <1%.
The diff coverage is 80%.

@@          Coverage Diff           @@
##             dev   #3131    +/-   ##
======================================
+ Coverage     80%     80%   +<1%     
======================================
  Files        353     353            
  Lines      27843   27847     +4     
  Branches    3690    3691     +1     
======================================
+ Hits       22182   22188     +6     
+ Misses      4608    4597    -11     
- Partials    1053    1062     +9

[snakefoot]

I received this error. I'm going home tonight and will see if I'm missing an attribute on the parameter nodes, but I've essentially mirrored your example + added my connection string.

Thanks for testing. Have updated the xml in the original issue-post with dbType for each parameter. Please update your test config and try again. See also: https://docs.microsoft.com/en-us/dotnet/api/system.data.dbtype

[D9001]

I received this error. I'm going home tonight and will see if I'm missing an attribute on the parameter nodes, but I've essentially mirrored your example + added my connection string.

Thanks for testing. Have updated the xml in the original issue-post with dbType for each parameter. Please update your test config and try again. See also: https://docs.microsoft.com/en-us/dotnet/api/system.data.dbtype

I tried adding dbType earlier, but I used "int32" as the documentation for DatabaseTarget had an example in lower case. But maybe it's case sensitive. I will try it out with "Int32" instead.

[snakefoot]

I tried adding dbType earlier, but I used "int32" as the documentation for DatabaseTarget had an example in lower case. But maybe it's case sensitive. I will try it out with "Int32" instead.

Else try doing this instead:

<parameter name="@level" layout="${level:format=ordinal}" dbType="SqlDbType.Int" />

[304NotModified]

System.InvalidOperationException: SqlCommand.Prepare method requires all parameters to have a
n explicitly set type.

PS: I think we won't do that by default, nor we can do because of backwards comp. So specify al DBtype attributes indeed

[D9001]

I tried adding dbType earlier, but I used "int32" as the documentation for DatabaseTarget had an example in lower case. But maybe it's case sensitive. I will try it out with "Int32" instead.

Else try doing this instead:

<parameter name="@level" layout="${level:format=ordinal}" dbType="SqlDbType.Int" />

I tried both Int32 and SqlDbType.Int with no luck yet; the same error appears. Does this configuration appear to be correct?

  <targets>
    <target name="asyncDatabase" type="AsyncWrapper" timeToSleepBetweenBatches="10000" queueLimit="100" overflowAction="Grow">
      <target name="wrapped_db" connectionstring="${gdc:item=ConnectionString}" xsi:type="Database" prepareDbCommand="True" keepConnection="true">
        <commandText>
          INSERT INTO Logging ([Identifier]) VALUES (@Id);
        </commandText>
        <parameter name="@Id" dbType="SqlDbType.Int" layout="${event-properties:item=Id}"/>
      </target>
    </target>
  </targets>

[304NotModified]

config looks valid. Could you please capture and post the internal log ? (trace level)

[D9001]

config looks valid. Could you please capture and post the internal log ? (trace level)

I forgot to post an update earlier, but this was due to a brain fart where I hadn't cleaned/rebuilt the solution so the nlog.config file being used was from my first attempt. I was able to bind the parameter in my example as well as dbTypes of SqlDbType.VarChar by specifying the size/length attributes as well. I have a meeting set up with our performance test engineer next Monday, so I can report back with how much the PrepareDbCommand method has improved performance that evening. This is my configuration:

    <target xsi:type="BufferingWrapper"
            name="aDb"
            bufferSize="100"
            flushTimeout="100000"
            overflowAction ="Flush">
      <target name="wrapped_db" connectionstring="..." xsi:type="Database" prepareDbCommand="True" keepConnection="true">
        <commandText>
          INSERT INTO Analytics ([AltId],[ManagerId],[Registration],[Eng],[Time]) VALUES (@AltId,@ManagerId,@Registration,@Eng,@Time);
        </commandText>
        <parameter name="@AltId" layout="${event-properties:item=AltId}" dbType="SqlDbType.VarChar" size="50" />
        <parameter name="@Eng" layout="${event-properties:item=Eng}" dbType="SqlDbType.VarChar" size="50"/>
        <parameter name="@ManagerId" layout="${event-properties:item=ManagerId}" dbType="SqlDbType.Int" />
        <parameter name="@Registration"  layout="${event-properties:item=Registration}" dbType="SqlDbType.VarChar" size="500"/>
        <parameter name="@Time" layout="${date:universalTime=true}" dbType="SqlDbType.DateTime" />
      </target>
    </target>

[304NotModified]

🎉 great news! Looking forward to the results!

[snakefoot]

... to measure is to know... :)

Don't mind removing the Prepare, and just change the parameter to be ReuseDbCommand

Extra caching is needed for SqlClient as SqlCommand-constructor starts as unprepared.

[snakefoot]

@D9001 Attached an updated build with caching of prepared DbCommands (See original post where new attachment has been added NLog.4.6.0-PS3131.nupkg.zip)

[snakefoot]

@D9001 Btw NLog tries to perform correct type-conversion based on DbType. But when using "special" types like SqlDbType.Int then it fails to guess the correct value-type. You can help NLog by doing this (Adding parameterType="System.Int32"):

<parameter name="@ManagerId" layout="${event-properties:item=ManagerId}" dbType="SqlDbType.Int" parameterType="System.Int32" />

NLog will guess correctly for standard DbType. But will only guess correctly for "special" DbTypes when the DbType contains: "Date", "TimeStamp", "Double", "Decimal", "Bool", "Guid". Alternative use dbType="Int32"

[D9001]

@snakefoot Thanks for the update. I've added the parameterType attributes for each parameter and have updated the NuGet package used in our test environment. For what it's worth, I am using this in a common library which targets .NET Standard 2.0, and the calling web application is a .NET Core 2.2 application.

update: I haven't started doing a full performance test, but I'm a little hesitant because I ran a simple test by writing a log 7 times, and the time it took in between each write still seemed rather slow. For example, after the first prepared statement was submitted, it took about 12 seconds before the next one was submitted, and nearly a second in between each right for the remaining 5 although all 7 were part of the same batch. With 5000-10000 logs being what would have normally been submitted in that timeframe, I don't think the results will have improved noticeably.

[snakefoot]

@D9001 Thank you for the update about what happens on the Server-side. Could you activate the NLog InternalLogger on Trace-Level, so one could see what happens on the Client-side?

See also: https://github.com/NLog/NLog/wiki/Internal-logging (You might have to check the log-file for sensitive information before posting it here on github).

Btw. if performance is important then you should NOT use the BufferingWrapper (Mostly for throttle and to ensure high latency). Instead use the AsyncWrapper as shown in the first post for this PR. Make sure that your logger-rules points to the name of the wrapper-target and not the database-target or else the batching will not be activated.

[D9001]

@D9001 Thank you for the update about what happens on the Server-side. Could you activate the NLog InternalLogger on Trace-Level, so one could see what happens on the Client-side?

See also: https://github.com/NLog/NLog/wiki/Internal-logging (You might have to check the log-file for sensitive information before posting it here on github).

Btw. if performance is important then you should NOT use the BufferingWrapper (Mostly for throttle and to ensure high latency). Instead use the AsyncWrapper as shown in the first post for this PR. Make sure that your logger-rules points to the name of the wrapper-target and not the database-target or else the batching will not be activated.

Ah, thanks for explaining that. I thought I had read that BufferingWrapper provided the same functionality as AsyncWrapper as long as sliding timeouts were enabled. I figured it was better since I originally thought it would create one long insert statement. I'll swap to the AsyncWrapper and test that out with internal logging enabled also.

[D9001]

Here's the internal logging from a regular non-performance run with some sensitive information I've omitted in between: https://justpaste.it/20eml

[snakefoot]

@D9001 That doesn't look good. Huge latency in the communication with the Database-instance. Guess a solution with sending an entire DataTable is needed for this case.

[snakefoot]

@D9001 Would you mind trying out #3150 ? (Use xsi:type="DataTable" instead of xsi:type="Database" and configure the new parameter updateBatchSize="200")

[snakefoot]

@304NotModified The changes in this PR should still reduce client-side overhead for those using the DatabaseTarget with a local database-instance (without high latency)

But I predict the extra complexity (of reusing the same DbCommand) will not pay itself off. Instead I just want the refactoring in this PR, but will remove the PrepareDbCommand-parameter again. Will create a new PR for this.

[304NotModified]

This can be closed in favor of #3150?

[snakefoot]

@304NotModified Have now removed the PrepareDbCommand-logic and instead just made the change to the new NLog 4.6 method: CreateDatabaseParameter

[304NotModified]

IMO this is more a retrieve/get then a create. It won't create (new) things?

[snakefoot]

It will create a value for all situations except when extracted rawvalue matches dbtype

[304NotModified]

It's a getOrCreate ;)

Not sure if we should have a virtual getOrCreate (need to check that)

IMO a create method should never "get”, so "get" is s better name (I'm trying to keep it easy to implement this method by others as it's virtual)

[snakefoot]

Renamed to GetDatabaseParameterValue