Thread: embedded sql regression from 8.2.4 to 8.3.7
I noticed a bit of a performance regression in embedded sql queries when
moving from the client libraries in verison 8.2.4 to 8.3.7. My
application does a whole lot of queries, many of which don't return any
data. When we moved to the new libraries the time of running a query
(from the application point of view) went from about 550 usec to 800
usec. In both cases this was against a server running 8.3.7.
I turned on log_statement_stats and noticed that the behaviour is
slightly different, and the 8.3.7 version sends the statement to the
server twice, while 8.2.4 only sends it once.
const char *SQL_text = "select * from foo"; (not always the same
query)
exec sql prepare s_1ab from :SQL_text; <---- [*1]
exec sql declare c_1ab cursor for s_1ab;
exec sql open c_1ab; <---- [*2]
At [*1], with the 8.3.7 libraries, I see in the server log:
STATEMENT: select * from foo
With 8.2.4, nothing is logged. Both versions send the statement to
declare the cursor:
STATEMENT: declare c_1ab cursor for select * from foo
Suggestions?
eric
Eric Haszlakiewicz wrote: > I noticed a bit of a performance regression in embedded sql queries when > moving from the client libraries in verison 8.2.4 to 8.3.7. My > application does a whole lot of queries, many of which don't return any > data. When we moved to the new libraries the time of running a query > (from the application point of view) went from about 550 usec to 800 > usec. In both cases this was against a server running 8.3.7. > I turned on log_statement_stats and noticed that the behaviour is > slightly different, and the 8.3.7 version sends the statement to the > server twice, while 8.2.4 only sends it once. > > const char *SQL_text = "select * from foo"; (not always the same query) > exec sql prepare s_1ab from :SQL_text; <---- [*1] > exec sql declare c_1ab cursor for s_1ab; > exec sql open c_1ab; <---- [*2] > > At [*1], with the 8.3.7 libraries, I see in the server log: > STATEMENT: select * from foo > > With 8.2.4, nothing is logged. Both versions send the statement to > declare the cursor: > STATEMENT: declare c_1ab cursor for select * from foo The log is misleading; the first statement is not really executed, it is only prepared (parsed). If you set the log level to DEBUG2, it will look like: DEBUG: parse s_1ab: select * from empsalary STATEMENT: select * from empsalary LOG: statement: begin transaction LOG: statement: declare c_1ab cursor for select * from empsalary The difference to 8.2 is that since 8.3, EXEC SQL PREPARE will result in a PREPARE statement on the server. In 8.2, no named prepared statement was created on the server, so nothing is logged in 8.2. The change in the source was here: http://archives.postgresql.org/pgsql-committers/2007-08/msg00185.php Maybe it is the additional PREPARE that slows your program. Are your queries complex enough that the PREPARE consumes significant time? Maybe you could use something like this to avoid the extra PREPARE: EXEC SQL BEGIN DECLARE SECTION; const char *SQL_text = "declare c_1ab cursor for select * from foo"; const char *fetch = "fetch from c_1ab"; int i; EXEC SQL END DECLARE SECTION; .... exec sql execute immediate :SQL_text; exec sql prepare fetch from :fetch; exec sql execute fetch into :i; It avoids the extra PREPARE, but looks pretty ugly. Yours, Laurenz Albe
>-----Original Message----- >From: Albe Laurenz [mailto:laurenz.albe@wien.gv.at] >> >> const char *SQL_text = "select * from foo"; (not always >the same query) >> exec sql prepare s_1ab from :SQL_text; <---- [*1] >> exec sql declare c_1ab cursor for s_1ab; >> exec sql open c_1ab; <---- [*2] >> >> At [*1], with the 8.3.7 libraries, I see in the server log: >> STATEMENT: select * from foo >> >> With 8.2.4, nothing is logged. Both versions send the statement to >> declare the cursor: >> STATEMENT: declare c_1ab cursor for select * from foo > >The log is misleading; the first statement is not really executed, >it is only prepared (parsed). If you set the log level to DEBUG2, it >will look like: Yes, but it's still incurring the overhead of sending the message to the server, isn't it? >The difference to 8.2 is that since 8.3, EXEC SQL PREPARE will result >in a PREPARE statement on the server. In 8.2, no named prepared >statement was created on the server, so nothing is logged in 8.2. > >The change in the source was here: >http://archives.postgresql.org/pgsql-committers/2007-08/msg00185.php > >Maybe it is the additional PREPARE that slows your program. >Are your queries complex enough that the PREPARE consumes >significant time? No, the queries aren't complex, but we prepare and excute hundred of queries, so it seems like the overhead of the extra message sent to the server adds up. >Maybe you could use something like this to avoid the >extra PREPARE: > EXEC SQL BEGIN DECLARE SECTION; > const char *SQL_text = "declare c_1ab cursor for select * >from foo"; > const char *fetch = "fetch from c_1ab"; > int i; > EXEC SQL END DECLARE SECTION; > .... > exec sql execute immediate :SQL_text; > exec sql prepare fetch from :fetch; > exec sql execute fetch into :i; > >It avoids the extra PREPARE, but looks pretty ugly. There are a number of things I could optimize once I start changing the code, such as just skipping the prepare entirely, but then I'd need to go through another whole release cycle of my app and I'd prefer not to do that right now. I was hoping there was a way to work around this by having Postgres not send that prepare to the server, but given the "major protocol rewrite" phrase on that commit log message you pointed me at, I'm guessing that's not possible. eric
>-----Original Message-----
>From: Albe Laurenz [mailto:laurenz.albe@wien.gv.at]
>Eric Haszlakiewicz wrote:
>> const char *SQL_text = "select * from foo"; (not always
>the same query)
>> exec sql prepare s_1ab from :SQL_text; <---- [*1]
>> exec sql declare c_1ab cursor for s_1ab;
>> exec sql open c_1ab; <---- [*2]
exec sql fetch c_1ab into :myvar;
>Maybe it is the additional PREPARE that slows your program.
>Are your queries complex enough that the PREPARE consumes
>significant time?
>
>Maybe you could use something like this to avoid the
>extra PREPARE:
>
> EXEC SQL BEGIN DECLARE SECTION;
> const char *SQL_text = "declare c_1ab cursor for select *
>from foo";
> const char *fetch = "fetch from c_1ab";
> int i;
> EXEC SQL END DECLARE SECTION;
>
> ....
> exec sql execute immediate :SQL_text;
> exec sql prepare fetch from :fetch;
> exec sql execute fetch into :i;
>
>It avoids the extra PREPARE, but looks pretty ugly.
That doesn't avoid an extra prepare entirely since the fetch statement
gets prepared, but it actually _is_ faster: 1360 usec to run the (real)
query my way, 910 usec your way (710usec w/ pg8.2.4). (wall clock time,
measured in the app)
The real queries are a little more complicated that the above example.
One might have a form a bit like this:
select varchar_col1, varchar_col2 from foo where colA = '12345' and
colB = 99 and colC = 'xyzabc' and colD like 'BLUE%';
The difference in wall clock time from the app point of view seems to
match up with the query stats from the db, (20 usec for the parsing the
fetch, 268 usec for the select) so it looks like re-writing things this
way would help somewhat.
oh, yuck. It looks like I can't get rid of the prepare entirely b/c I
can't declare a cursor using a sql string. i.e.:
exec sql declare c_1ab cursor for :SQL_text;
actually means something more like:
exec sql declare c_1ab cursor for :statement_name;
Also, I can't use execute immediate with host variables, so I guess I'm
stuck preparing stuff. :(
eric
Eric Haszlakiewicz wrote: >> The log is misleading; the first statement is not really executed, >> it is only prepared (parsed). If you set the log level to DEBUG2, it >> will look like: > > Yes, but it's still incurring the overhead of sending the message to the > server, isn't it? Yes. >> Maybe it is the additional PREPARE that slows your program. >> Are your queries complex enough that the PREPARE consumes >> significant time? > > No, the queries aren't complex, but we prepare and excute hundred of > queries, so it seems like the overhead of the extra message sent to the > server adds up. I see. > I was hoping there was a way to work around this by > having Postgres not send that prepare to the server, but given the > "major protocol rewrite" phrase on that commit log message you pointed > me at, I'm guessing that's not possible. It looks like what is normally an advantage (having named prepared statements that can be reused) makes things slower in your case, since you do not use the prepared statement at all and only need it to be able to use a cursor with dynamic SQL. Yours, Laurenz Albe