Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

performance: round-trip/sql invocation cost [DNET280] #291

Closed
firebird-automations opened this issue Oct 29, 2009 · 15 comments
Closed

performance: round-trip/sql invocation cost [DNET280] #291

firebird-automations opened this issue Oct 29, 2009 · 15 comments

Comments

@firebird-automations
Copy link

Submitted by: Vasily Kabanov (vaso)

Attachments:
Program.cs
IbxSpeedTest.dpr

Votes: 1

I tried populating simple test table with parameterized insert statement. It was very slow (~270 rows/second). Processor utilization was 15-40%, 60-70% of which - in kernel (which to me was a sign of something unproductive going on).
1st, I suspected query re-parsing to be a problem and packaged insert into a SP, no luck.
2nd, suspected character sets convertions for strings and left only integer parameters, again slow.
finally, suspected some marshaling or reflection issues and tried .NET over ODBC.
Parameterized insert was slow again, but when using stored proc performance went up: 6500 rows/second which is excellent.

@firebird-automations
Copy link
Author

Modified by: Vasily Kabanov (vaso)

description: I tried populating simple test table with parameterized insert statement. It was very slow (~270 rows/second). Processor utilization was 60-70% in kernel (which to me is a sign of something unproductive going on).
1st, I suspected query re-parsing to be a problem and packaged insert into a SP, no luck.
2nd, suspected character sets convertions for strings and left only integer parameters, again slow.
finally, suspected some marshaling or reflection issues and tried .NET over ODBC.
Parameterized insert was slow again, but when using stored proc performance went up: 6500 rows/second which is excellent.

=>

I tried populating simple test table with parameterized insert statement. It was very slow (~270 rows/second). Processor utilization was 15-40%, 60-70% of which - in kernel (which to me was a sign of something unproductive going on).
1st, I suspected query re-parsing to be a problem and packaged insert into a SP, no luck.
2nd, suspected character sets convertions for strings and left only integer parameters, again slow.
finally, suspected some marshaling or reflection issues and tried .NET over ODBC.
Parameterized insert was slow again, but when using stored proc performance went up: 6500 rows/second which is excellent.

@firebird-automations
Copy link
Author

Commented by: @cincuranet

How is you code looking?

@firebird-automations
Copy link
Author

Commented by: Vasily Kabanov (vaso)

The way the code is looking is pretty much irrelevant here I guess. I mean even absolutely empty command is slow to invoke. Example:

create or alter procedure sp_test_empty
as
begin
end

---------------
// connection string: "server type=Embedded;user id=SYSDBA;password=masterkey;data source=localhost;dialect=3;character set=NONE;packet size=8192;initial catalog=C:\data\dbfiles\FBTEST.FDB;client library=C:\distr\dev\Interbase\FireBird\Embed\fbembed.dll"
static void TestFirebirdEmpty()
{
using (fb.FbConnection cn = GetFirebirdConnection())
{
using (fb.FbCommand cmd = cn.CreateCommand())
{
cmd.CommandText = "sp_test_empty";
cmd.CommandType = System.Data.CommandType.StoredProcedure;
const int recCount = 100000;

		cmd\.Prepare\(\);
		DateTime start = DateTime\.Now;
		for \(int n = 0; n < recCount; \+\+n\)
		\{
			cmd\.ExecuteNonQuery\(\);
		\}
		DateTime finish = DateTime\.Now;

		double seconds = \(finish \- start\)\.TotalSeconds;

		Console\.WriteLine\("\{0\} commands in \{1\} seconds; \{2\} commands per second", recCount, seconds, recCount / seconds\);
	\}
\}

}
------------------------
Output:
100000 commands in 148.3857132 seconds; 673.919327160669 commands per second.

I am using embedded Firebird (which should probably be faster than superserver), but I also tried superserver, it was slow too.

Same code via .NET over ODBC ({call sp_test_empty}):
100000 commands in 3.4913491 seconds; 28642.223145202 commands per second

@firebird-automations
Copy link
Author

Modified by: @cincuranet

priority: Major [ 3 ] => Minor [ 4 ]

@firebird-automations
Copy link
Author

Commented by: F.D.Castel (fdcastel)

Benchmarks for Firebird http://ADO.NET Data Provider , ODBC and Delphi/IBX

@firebird-automations
Copy link
Author

Modified by: F.D.Castel (fdcastel)

Attachment: Program.cs [ 12277 ]

Attachment: IbxSpeedTest.dpr [ 12278 ]

@firebird-automations
Copy link
Author

Commented by: F.D.Castel (fdcastel)

New benchmarks. Using http://FB.Net Data Provider 3.0.2, Firebird 2.5.2 x64 SuperServer running on local machine

I also made a Delphi 2007/IBX test to compare. Source code attached, The results are really something:

-----
http://FB.Net: 100000 commands in 39,308 seconds; 2544,01139717106 commands per second
ODBC: 100000 commands in 3,015 seconds; 33167,495854063 commands per second
IBX: 100000 commands in 1,38000031001866 seconds; 72463,7518368731 commands per second
-----

@firebird-automations
Copy link
Author

Commented by: F.D.Castel (fdcastel)

Profiling the code, I found several calls to

FirebirdSql\.Data\.FirebirdClient\.FbCommand\.CommitImplicitTransaction\(\)

So... Changing the sample code to use explicit transactions made a huge gain:

http://FB.Net: 100000 commands in 12,643 seconds; 7909,51514672151 commands per second
ODBC: 100000 commands in 3,049 seconds; 32797,638570023 commands per second

but yet, 4x slower than ODBC and 10x slower than Delphi:

IBX: 100000 commands in 1,37200020253658 seconds; 72886,2866165164 commands per second (*)

(*) IBX obliges you to use explicit transactions, so the Delphi code was already using them.

I'll continue to profile the code trying to find where the bottleneck is.

Meanwhile, it is worthy of notice that ODBC code doesn't suffer from using implicit transactions. Maybe that call to FbCommand.CommitImplicitTransaction() should be rethought

@firebird-automations
Copy link
Author

Commented by: F.D.Castel (fdcastel)

Another cause for large slowdowns is a call to LogCommand() in FbCommand.Prepare(bool):

* Official Build
http://FB.Net: 100000 commands in 12,581 seconds; 7948,4937604324 commands per second
ODBC: 100000 commands in 3,027 seconds; 33036,0092500826 commands per second

* /trunk build without LogCommand() call
http://FB.Net: 100000 commands in 7,291 seconds; 13715,5397064875 commands per second
ODBC: 100000 commands in 3,036 seconds; 32938,0764163373 commands per second

However, this function is marked with a conditional TRACE attribute.

* /trunk build without TRACE compiler directive
http://FB.Net: 100000 commands in 7,297 seconds; 13704,2620254899 commands per second
ODBC: 100000 commands in 3,034 seconds; 32959,78905735 commands per second

Bottom line: the current distribution (3.0.2) were built with TRACE directive turned on.

@firebird-automations
Copy link
Author

Commented by: @cincuranet

Did you had any listener attached/defined?

@firebird-automations
Copy link
Author

Commented by: F.D.Castel (fdcastel)

No. It was a simple program (source code attached) built as Release (not a Debug build) and running outside the IDE (without a debugger attached)

This program, running with the Official build, took 12.5 seconds.

Just replacing the FirebirdSql.Data.FirebirdClient.dll (with the one built without TRACE directive) it took 7.2 seconds.

The TRACE directive should not be removed on Release builds?

@firebird-automations
Copy link
Author

Commented by: @cincuranet

With the help of DNET895 the performance of ODBC is on par with FirebirdClient.

For the Delphi part I'm getting about 8200 op/s (I modified the source to explicitly use localhost to prevent direct file usage), while .NET and ODBC is about half of that. But that's going to need some deeper investigation, because it's not exactly apples-to-apples comparison. I'll leave this open, in case somebody would want to start profiling sooner than me.

@firebird-automations
Copy link
Author

Modified by: @cincuranet

status: Open [ 1 ] => In Progress [ 3 ]

@firebird-automations
Copy link
Author

Modified by: @cincuranet

status: In Progress [ 3 ] => Open [ 1 ]

@cincuranet
Copy link
Member

Closing now in favor of specific performance tasks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants