Thread: 8.0.1 performance question.

Hi,

I have just upgraded our db from 7.4.2 to 8.0.1 and we are doing some
testing.  For some reasons, we have discovered that  our application
performs much slower on 8.0.1.

My initial reaction was to turn on  log_min_duration_statement to see
what's happening.  However, log_min_duration_statement does not work
for JDBC clients in 8.0.1.

As a result, I modified log_statement to all.  Without my application
doing anything, I see statements below being executed non-stop.  Who
is triggering these statemetns?  Is this normal?  What am I doing
wrong?

I am using Fedora Core 1 - Kernel: 2.4.22-1.2174.nptl

Please help.  Thanks.

PS.  I sent this email to the performance list and Tom asked me to
check with this list.  Therefore, here I am.

2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
(a.attrelid=c.oid
) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
L
IKE '%nextval(%'


---------- Forwarded message ----------
From: Tom Lane <tgl@sss.pgh.pa.us>
Date: Apr 4, 2005 11:49 PM
Subject: Re: [PERFORM] 8.0.1 performance question.
To: alvin.yk@gmail.com
Cc: pgsql-performance@postgresql.org


<alvin.yk@gmail.com> writes:
> As a result, I modified log_statement to all.  Without my application
> doing anything, I see statements below being executed non-stop.  Who
> is triggering these statemetns?  Is this normal?  What am I doing
> wrong?

> 2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
> pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
> 2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
> pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
> (a.attrelid=c.oid
> ) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
> a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
> L
> IKE '%nextval(%'

Better ask about that on pgsql-jdbc.  I suppose this is the trace of the
JDBC driver trying to find out column metadata ... but if it's failing
to cache the information that's a pretty serious performance hit.

                        regards, tom lane

On Tue, 5 Apr 2005 alvin.yk@gmail.com wrote:

> I see statements below being executed non-stop.  Who is triggering these
> statemetns?  Is this normal?  What am I doing wrong?
>
>
> 2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
> pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
> 2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
> pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
> (a.attrelid=c.oid
> ) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
> a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
> L
> IKE '%nextval(%'

These are the results of ResultSetMetaData.isNullable() and
isAutoIncrement(), which your code is apparently calling.  The results of
these calls are cached on a per ResultSet data.  We have discussed
caching them at a higher level, but couldn't find a way to know when to
flush that cache.

Kris Jurka

Thank you for the quick response.  To help me debug what's happening,
can you tell me what's the difference between the 7.4 and 8.0 jdbc
drivers in this regard?  Is this something that is newly introduced in
8.0?  Or is this something that has always been happening?

Thanks.



On Apr 5, 2005 12:15 AM, Kris Jurka <books@ejurka.com> wrote:
>
>
> On Tue, 5 Apr 2005 alvin.yk@gmail.com wrote:
>
> > I see statements below being executed non-stop.  Who is triggering these
> > statemetns?  Is this normal?  What am I doing wrong?
> >
> >
> > 2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT attnotnull FROM
> > pg_catalog.pg_attribute WHERE attrelid = $1 AND attnum = $2
> > 2005-04-04 18:05:00 CST PARSELOG:  statement: SELECT def.adsrc FROM
> > pg_catalog.pg_class c JOIN pg_catalog.pg_attribute a ON
> > (a.attrelid=c.oid
> > ) LEFT JOIN pg_catalog.pg_attrdef def ON (a.attrelid=def.adrelid AND
> > a.attnum = def.adnum) WHERE c.oid = $1 and a.attnum = $2 AND def.adsrc
> > L
> > IKE '%nextval(%'
>
> These are the results of ResultSetMetaData.isNullable() and
> isAutoIncrement(), which your code is apparently calling.  The results of
> these calls are cached on a per ResultSet data.  We have discussed
> caching them at a higher level, but couldn't find a way to know when to
> flush that cache.
>
> Kris Jurka
>

On Tue, 5 Apr 2005 alvin.yk@gmail.com wrote:

> Thank you for the quick response.  To help me debug what's happening,
> can you tell me what's the difference between the 7.4 and 8.0 jdbc
> drivers in this regard?  Is this something that is newly introduced in
> 8.0?  Or is this something that has always been happening?
>

8.0 is the first driver version to take advantage of the V3 protocol's
ability to return the base tables and columns of a ResultSet.
Previously isNullable was hardcoded to always return
columnNullableUnknown and isAutoIncrement always returned false.

I guess the question is why are you calling these methods if they didn't
work previously?

Kris Jurka