Bind variables vs. literals, a quiz and a surprise

The quiz

Recently, something I had intended to be a simple demo promoting the use of bind variables among Java developers turned out to be more interesting than expected.
It all started as a quiz. So I was going to ask, how long would the following run:

  • a fixed query, repeated 100,000 times, always with the same literal
  • the same query, again repeated 100,000 times, but this time using a bind variable, the same value every time
  • the same query, repeated 100,000 times, using 100,000 different literals
  • the same query, repeated 100,000 times, using 100,000 different values for the bind variable

Just so you know what I did exactly, this is how the Java code looked (displaying the relevant parts here only):

One same literal, 100,000 times

String query = "select text1, text2 from mytab where rn=";
int id = 1;
long startTime = System.currentTimeMillis();
Statement stmt = conn.createStatement();
for (int i = 0; i <= 100000; i++) {
  ResultSet rset = stmt.executeQuery (query + id);
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
}
stmt.close();
System.out.println(System.currentTimeMillis() - startTime);
conn.close();

One same bind value, 100,000 times

String query = "select text1, text2 from mytab where rn=?";
int id = 1;
long startTime = System.currentTimeMillis();
PreparedStatement stmt = conn.prepareStatement(query);
for (int i=0; i<= 100000; i++) {
  stmt.setInt(1, id);
  ResultSet rset = stmt.executeQuery();
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
}
stmt.close();
System.out.println(System.currentTimeMillis() - startTime);
conn.close();

100,000 different literals

String query = "select text1, text2 from mytab where rn=";
int id = 1;
long startTime = System.currentTimeMillis();
Statement stmt = conn.createStatement();
for (int i = 0; i<= 100000; i++) {
  ResultSet rset = stmt.executeQuery (query + id);
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
  id = id + 1;
}
stmt.close();
System.out.println(System.currentTimeMillis() - startTime);
conn.close();

100,000 different bind values

String query = "select text1, text2 from mytab where rn=?";
int id = 1;
long startTime = System.currentTimeMillis();
PreparedStatement stmt = conn.prepareStatement(query);
for (int i = 0; i<= 100000; i++) {
  stmt.setInt(1, id);
  ResultSet rset = stmt.executeQuery();
  String s;
  while (rset.next ()) {
    s = rset.getString (1) + " " + rset.getString (2);
  }
  rset.close();
  id = id + 1;
}
stmt.close();
conn.close();

So, of course what I intended to show was the devastating effect of using different literals all the time. Which I succeeded in. But let’s look at the results, first, the execution times measured on the client side:

Client-side execution times (ms)
One same literal 36.1
One same bind value 24.7
100,000 literals 147.4
100,000 bind values 25.3

The surprise

Nice. The 100,000 different literals case does have a horrible execution time. But let’s look at the one-same-value cases, same literal vs. same bind value. Why is the bind variable case so much faster?
(And by the way, although I’m listing the results of one trial only, they were totally reproducible, the pattern was the same how ever I varied the circumstances – e.g., with/without tracing …)

In the one-same-literal case, we perform one hard parse and two soft parses, – from there on it’s “softer soft parses” only.
This can nicely be seen in the trace file. In the third CLOSE line, we have type=1, and PARSE elapsed times are <30 microseconds from there on:

PARSING IN CURSOR ...
PARSE #140263995577416:c=2999,e=20813,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2832086359,tim=1420822842233661
EXEC #140263995577416:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842238446
WAIT #140263995577416: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842238488
FETCH #140263995577416:c=0,e=110,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842238639
..
WAIT #140263995577416: nam='SQL*Net message from client' ela= 101732 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842340650
CLOSE #140263995577416:c=0,e=15,dep=0,type=0,tim=1420822842340788
=====================
PARSING IN CURSOR ... 
PARSE #140263995577416:c=0,e=199,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842341057
EXEC #140263995577416:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842341161
WAIT #140263995577416: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842341197
FETCH #140263995577416:c=0,e=44,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842341312
...
WAIT #140263995577416: nam='SQL*Net message from client' ela= 1708 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842343128
CLOSE #140263995577416:c=0,e=8,dep=0,type=0,tim=1420822842343193
=====================
PARSING IN CURSOR ...
PARSE #140263995577416:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842343301
EXEC #140263995577416:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842343386
WAIT #140263995577416: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842343414
FETCH #140263995577416:c=0,e=29,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842343467
...
WAIT #140263995577416: nam='SQL*Net message from client' ela= 1618 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842345279
CLOSE #140263995577416:c=0,e=14,dep=0,type=1,tim=1420822842345357
PARSE #140263995577416:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842345420
EXEC #140263995577416:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420822842345473
WAIT #140263995577416: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842345502
FETCH #140263995577416:c=0,e=27,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420822842345568
WAIT #140263995577416: nam='SQL*Net message from client' ela= 1618 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420822842347230
CLOSE #140263995577416:c=0,e=11,dep=0,type=3,tim=1420822842347318

From a visual inspection of the trace file for the one-same-bind-value case, you might think both cases should take about the same time in the end:

PARSING IN CURSOR ...
PARSE #140450201769032:c=0,e=873,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1420823096225812
EXEC #140450201769032:c=2000,e=2337,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2832086359,tim=1420823096228602
WAIT #140450201769032: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096228684
FETCH #140450201769032:c=0,e=112,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420823096228869
...
WAIT #140450201769032: nam='SQL*Net message from client' ela= 83168 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096312251
EXEC #140450201769032:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420823096312442
WAIT #140450201769032: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096312507
FETCH #140450201769032:c=0,e=60,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420823096312527
WAIT #140450201769032: nam='SQL*Net message from client' ela= 1081 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096313684
EXEC #140450201769032:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2832086359,tim=1420823096313794
WAIT #140450201769032: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1420823096313832
FETCH #140450201769032:c=0,e=35,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=2832086359,tim=1420823096313848

How does this go together then – on the one hand, the work done by the database does not seem to be tremendously different, on the other, the bind values case is noticeably faster on the client!

Well, let’s look at a statistical summary of the database calls for both cases.
First, the one-same-literal case:

1 same literal, 100,000 times
call type count sum elapsed avg elapsed stddev elapsed median elapsed
PARSE 100001 1850716 19 20 16
EXEC 100001 1207545 12 12 11
FETCH 100001 1384287 14 17 12
CLOSE 100000 335618 3 4 3
overall db 400003 4778166
1 same bind value, 100,000 times
call type count sum elapsed avg elapsed stddev elapsed median elapsed
PARSE 1 202 202 0 202
EXEC 100001 1388479 14 25 12
FETCH 100001 3080674 31 30 28
CLOSE 0
overall db 200003 4469355

So it’s true, seen from the database side, the elapsed times for both cases do not differ much at all!
So really the database is doing about the same amount of work in both cases.

Wait a sec …

What about when we add the wait time, especially, SQL*NET message from client (overall db calls are the db call summary numbers from above)?

1 same literal, 100,000 times
type count sum elapsed avg elapsed stddev elapsed median elapsed
SQL*NET msg from client 100001 15308493 153 949 106
overall db calls 400003 4778166
overall total 500004 20086659
1 same bind value, 100,000 times
type count sum elapsed avg elapsed stddev elapsed median elapsed
SQL*NET msg from client 100001 11425310 114 416 74
overall db calls 200003 4469355
overall total 300004 15894665

So we see it is really the time subsumed under SQL*NET message from client that makes the difference.
Why? A SQL*NET trace shows that the amount of data transferred over the network is about twice as much for the literals case than for the binds case (156 vs. 70 bytes per execution). Of course, that’s way below TCP packet size in both cases, but the data has to pass various layers where the size of the read/write operations might make a difference. Probably, the biggest factor here might be the processing on the Java client side, the client having to marshal either a simple number or a not-too-short string. (Of course, that’s just a guess which would need to be supported by more sophisticated measurements on the client side.)

So what’s the conclusion? We can be even more confident about advising (Java) developers to use bind variables, because response times will go down even in cases where one (me, at least) wouldn’t have expected to see a noticeable difference 🙂

Advertisements

2 thoughts on “Bind variables vs. literals, a quiz and a surprise

  1. I was curious what the profiles for your two trace excerpts look like, so I summed them up (I wish I knew how to make it a fixed-width font):

    $ mrskew 1.trc # your first excerpt
    CALL-NAME DURATION % CALLS MEAN MIN MAX
    ————————— ——– —— —– ——– ——– ——–
    SQL*Net message from client 0.106676 97.3% 4 0.026669 0.001618 0.101732
    PARSE 0.002999 2.7% 4 0.000750 0.000000 0.002999
    SQL*Net message to client 0.000009 0.0% 4 0.000002 0.000001 0.000004
    FETCH 0.000000 0.0% 4 0.000000 0.000000 0.000000
    CLOSE 0.000000 0.0% 4 0.000000 0.000000 0.000000
    EXEC 0.000000 0.0% 4 0.000000 0.000000 0.000000
    ————————— ——– —— —– ——– ——– ——–
    TOTAL (6) 0.109684 100.0% 24 0.004570 0.000000 0.101732

    $ mrskew 2.trc # your second excerpt
    CALL-NAME DURATION % CALLS MEAN MIN MAX
    ————————— ——– —— —– ——– ——– ——–
    SQL*Net message from client 0.084249 97.7% 2 0.042125 0.001081 0.083168
    EXEC 0.002000 2.3% 3 0.000667 0.000000 0.002000
    SQL*Net message to client 0.000007 0.0% 3 0.000002 0.000001 0.000004
    PARSE 0.000000 0.0% 1 0.000000 0.000000 0.000000
    FETCH 0.000000 0.0% 3 0.000000 0.000000 0.000000
    ————————— ——– —— —– ——– ——– ——–
    TOTAL (5) 0.086256 100.0% 12 0.007188 0.000000 0.083168

  2. Cary,

    thanks for commenting! I used my external tables approach for the statistical summaries, but if you’d like to verify using mrskew, I could send you the complete trace files…

    Cheers
    Sigrid

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s