Received: from magus.postgresql.org (magus.postgresql.org [87.238.57.229]) by mail.postgresql.org (Postfix) with ESMTP id 979502F4278 for ; Wed, 21 Mar 2012 10:00:10 -0300 (ADT) Received: from mh6.mail.rice.edu ([128.42.201.4]) by magus.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1SAL93-00069I-EQ for pgsql-performance@postgresql.org; Wed, 21 Mar 2012 13:00:09 +0000 Received: from mh6.mail.rice.edu (localhost.localdomain [127.0.0.1]) by mh6.mail.rice.edu (Postfix) with ESMTP id 97DA92911B9; Wed, 21 Mar 2012 07:59:30 -0500 (CDT) Received: from mh6.mail.rice.edu (localhost.localdomain [127.0.0.1]) by mh6.mail.rice.edu (Postfix) with ESMTP id 89F422911A9; Wed, 21 Mar 2012 07:59:30 -0500 (CDT) X-Virus-Scanned: by amavis-2.6.4 at mh6.mail.rice.edu, auth channel Received: from mh6.mail.rice.edu ([127.0.0.1]) by mh6.mail.rice.edu (mh6.mail.rice.edu [127.0.0.1]) (amavis, port 10026) with ESMTP id AigHeM4qu2dG; Wed, 21 Mar 2012 07:59:30 -0500 (CDT) X-SMTP-Auth: no X-SMTP-Auth: no Received: from aart.rice.edu (aart.rice.edu [168.7.56.48]) by mh6.mail.rice.edu (Postfix) with ESMTP id 51A252911B9; Wed, 21 Mar 2012 07:59:30 -0500 (CDT) Received: by aart.rice.edu (Postfix, from userid 18612) id 46FBF1002CB; Wed, 21 Mar 2012 07:59:30 -0500 (CDT) Date: Wed, 21 Mar 2012 07:59:30 -0500 From: "ktm@rice.edu" To: Rafael Martinez Cc: pgsql-performance@postgresql.org Subject: Re: DBD-Pg prepared statement versus plain execution Message-ID: <20120321125930.GA7440@aart.rice.edu> References: <4F69B9B3.7030303@usit.uio.no> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <4F69B9B3.7030303@usit.uio.no> User-Agent: Mutt/1.5.20 (2009-12-10) X-Pg-Spam-Score: -4.2 (----) X-Archive-Number: 201203/134 X-Sequence-Number: 46584 Hi Rafael, Try disabling the prepare statement processing in DBD::Pg and try the timing runs again. Regards, Ken On Wed, Mar 21, 2012 at 12:21:23PM +0100, Rafael Martinez wrote: > -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA1 > > Hello > > We are having some performance problems with an application that uses > prepared statement heavily. > > We have found out that it creates-executes-destroys a prepared statement > *per* statement it sends to the database (pg-9.1) via DBD-Pg. > > A normal log entry for a sql-statement looks e.g. like this: > - ---------------------------------------------------------- > [2012-03-15 14:49:12.484 CET] LOG: duration: 8.440 ms parse > dbdpg_p32048_3: > > SELECT DISTINCT ACL.RightName FROM ACL, Principals, CachedGroupMembers > WHERE Principals.id = ACL.PrincipalId AND Principals.PrincipalType = > 'Group' AND Principals.Disabled = 0 AND CachedGroupMembers.GroupId = > ACL.PrincipalId AND CachedGroupMembers.GroupId = Principals.id AND > CachedGroupMembers.MemberId = 19312 AND CachedGroupMembers.Disabled = 0 > AND ((ACL.ObjectType = 'RT::System' AND ACL.ObjectId = 1) OR > (ACL.ObjectType = 'RT::System' AND ACL.ObjectId = 1)) > > [2012-03-15 14:49:12.485 CET] LOG: duration: 0.087 ms bind > dbdpg_p32048_3: > > SELECT DISTINCT ACL.RightName FROM ACL, Principals, CachedGroupMembers > WHERE Principals.id = ACL.PrincipalId AND Principals.PrincipalType = > 'Group' AND Principals.Disabled = 0 AND CachedGroupMembers.GroupId = > ACL.PrincipalId AND CachedGroupMembers.GroupId = Principals.id AND > CachedGroupMembers.MemberId = 19312 AND CachedGroupMembers.Disabled = 0 > AND ((ACL.ObjectType = 'RT::System' AND ACL.ObjectId = 1) OR > (ACL.ObjectType = 'RT::System' AND ACL.ObjectId = 1)) > > > [2012-03-15 14:49:12.487 CET] LOG: duration: 1.692 ms execute > dbdpg_p32048_3: > > SELECT DISTINCT ACL.RightName FROM ACL, Principals, CachedGroupMembers > WHERE Principals.id = ACL.PrincipalId AND Principals.PrincipalType = > 'Group' AND Principals.Disabled = 0 AND CachedGroupMembers.GroupId = > ACL.PrincipalId AND CachedGroupMembers.GroupId = Principals.id AND > CachedGroupMembers.MemberId = 19312 AND CachedGroupMembers.Disabled = 0 > AND ((ACL.ObjectType = 'RT::System' AND ACL.ObjectId = 1) OR > (ACL.ObjectType = 'RT::System' AND ACL.ObjectId = 1)) > > > [2012-03-15 14:49:12.488 CET] LOG: duration: 0.029 ms statement: > DEALLOCATE dbdpg_p32048_3 > - ---------------------------------------------------------- > > As you can see, the parse+bind+deallocate part uses much more time than > the execution part. This is the same for many of the statements send to > the database. > > My question is: > > Is the parse+bind time reported, a time (not reported) that the planer > will use anyway when running a sql-statement in a normal way or the > parse+bind+deallocate time is *extra* time needed by the prepared statement? > > Can we assume that running this application without using prepared > statements will do that it runs faster the time used by > parse+bind+deallocate? > > Thanks in advance. > > regards, > - -- > Rafael Martinez Guerrero > Center for Information Technology > University of Oslo, Norway > > PGP Public Key: http://folk.uio.no/rafael/ > -----BEGIN PGP SIGNATURE----- > Version: GnuPG v1.4.10 (GNU/Linux) > Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ > > iEYEARECAAYFAk9pubAACgkQBhuKQurGihTYkwCcCFYQRDGWD0yaR+f2FFwKs7gN > RfgAoJdPrAzUhfBfsXmst7/l7LVLisHy > =l7Fl > -----END PGP SIGNATURE----- > > -- > Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-performance >