Help needed for reading postgres log : RE: Concurrency issue under very heay loads

I would like some help in reading the postgres logs.
Here is a snippet of the log.
Auto commit seems to be set to false.
But still the logs shows "CommitTransactionCommand" in debug mode.
The same order number is given for multiple clients.
Please see "CommitTransactionCommand" below for both "select ...for
update" and "update..." SQLs and let me know if I am reading correctly
that auto commit is actually effective.
Thanks
Raji
-----
2009-07-17 14:10:59 4736 970134 DEBUG: parse <unnamed>: SELECT
nextEntityID FROM tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 DEBUG: StartTransactionCommand
2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 DEBUG: parse tree:
2009-07-17 14:10:59 4736 970134 DETAIL: {QUERY
:commandType 1
:querySource 0
:canSetTag true
:utilityStmt <>
:resultRelation 0
:into <>
:intoOptions <>
:intoOnCommit 0
:intoTableSpaceName <>
:hasAggs false
:hasSubLinks false
:rtable (
{RTE
:alias <>
:eref
{ALIAS
:aliasname tableentityid
:colnames ("entitytype" "nextentityid")
}
:rtekind 0
:relid 16420
:inh true
:inFromCl true
:requiredPerms 6
:checkAsUser 0
}
)
:jointree
{FROMEXPR
:fromlist (
{RANGETBLREF
:rtindex 1
}
)
:quals
{OPEXPR
:opno 98
:opfuncid 0
:opresulttype 16
:opretset false
:args (
{RELABELTYPE
:arg
{VAR
:varno 1
:varattno 1
:vartype 1043
:vartypmod 68
:varlevelsup 0
:varnoold 1
:varoattno 1
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
{RELABELTYPE
:arg
{PARAM
:paramkind 0
:paramid 1
:paramtype 1043
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
)
}
}
:targetList (
{TARGETENTRY
:expr
{VAR
:varno 1
:varattno 2
:vartype 1043
:vartypmod 132
:varlevelsup 0
:varnoold 1
:varoattno 2
}
:resno 1
:resname nextentityid
:ressortgroupref 0
:resorigtbl 16420
:resorigcol 2
:resjunk false
}
)
:returningList <>
:groupClause <>
:havingQual <>
:distinctClause <>
:sortClause <>
:limitOffset <>
:limitCount <>
:rowMarks (
{ROWMARKCLAUSE
:rti 1
:forUpdate true
:noWait false
}
)
:setOperations <>
:resultRelations <>
:returningLists <>
}

2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 DEBUG: rewritten parse tree:
2009-07-17 14:10:59 4736 970134 DETAIL: (
{QUERY
:commandType 1
:querySource 0
:canSetTag true
:utilityStmt <>
:resultRelation 0
:into <>
:intoOptions <>
:intoOnCommit 0
:intoTableSpaceName <>
:hasAggs false
:hasSubLinks false
:rtable (
{RTE
:alias <>
:eref
{ALIAS
:aliasname tableentityid
:colnames ("entitytype" "nextentityid")
}
:rtekind 0
:relid 16420
:inh true
:inFromCl true
:requiredPerms 6
:checkAsUser 0
}
)
:jointree
{FROMEXPR
:fromlist (
{RANGETBLREF
:rtindex 1
}
)
:quals
{OPEXPR
:opno 98
:opfuncid 0
:opresulttype 16
:opretset false
:args (
{RELABELTYPE
:arg
{VAR
:varno 1
:varattno 1
:vartype 1043
:vartypmod 68
:varlevelsup 0
:varnoold 1
:varoattno 1
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
{RELABELTYPE
:arg
{PARAM
:paramkind 0
:paramid 1
:paramtype 1043
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
)
}
}
:targetList (
{TARGETENTRY
:expr
{VAR
:varno 1
:varattno 2
:vartype 1043
:vartypmod 132
:varlevelsup 0
:varnoold 1
:varoattno 2
}
:resno 1
:resname nextentityid
:ressortgroupref 0
:resorigtbl 16420
:resorigcol 2
:resjunk false
}
)
:returningList <>
:groupClause <>
:havingQual <>
:distinctClause <>
:sortClause <>
:limitOffset <>
:limitCount <>
:rowMarks (
{ROWMARKCLAUSE
:rti 1
:forUpdate true
:noWait false
}
)
:setOperations <>
:resultRelations <>
:returningLists <>
}
)

2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 LOG: duration: 0.000 ms
2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 DEBUG: bind <unnamed> to <unnamed>
2009-07-17 14:10:59 4736 970134 DEBUG: plan:
2009-07-17 14:10:59 4736 970134 DETAIL: {SEQSCAN
:startup_cost 0.00
:total_cost 4.05
:plan_rows 1
:plan_width 12
:targetlist (
{TARGETENTRY
:expr
{VAR
:varno 1
:varattno 2
:vartype 1043
:vartypmod 132
:varlevelsup 0
:varnoold 1
:varoattno 2
}
:resno 1
:resname nextentityid
:ressortgroupref 0
:resorigtbl 16420
:resorigcol 2
:resjunk false
}
{TARGETENTRY
:expr
{VAR
:varno 1
:varattno -1
:vartype 27
:vartypmod -1
:varlevelsup 0
:varnoold 1
:varoattno -1
}
:resno 2
:resname ctid1
:ressortgroupref 0
:resorigtbl 0
:resorigcol 0
:resjunk true
}
)
:qual (
{OPEXPR
:opno 98
:opfuncid 67
:opresulttype 16
:opretset false
:args (
{RELABELTYPE
:arg
{VAR
:varno 1
:varattno 1
:vartype 1043
:vartypmod 68
:varlevelsup 0
:varnoold 1
:varoattno 1
}
:resulttype 25
:resulttypmod -1
:relabelformat 0
}
{CONST
:consttype 25
:constlen -1
:constbyval false
:constisnull false
:constvalue 10 [ 10 0 0 0 119 105 122 97 114 100 ]
}
)
}
)
:lefttree <>
:righttree <>
:initPlan <>
:extParam (b)
:allParam (b)
:nParamExec 0
:scanrelid 1
}

2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 LOG: duration: 0.000 ms
2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 LOG: duration: 0.000 ms
2009-07-17 14:10:59 4736 970134 STATEMENT: SELECT nextEntityID FROM
tableEntityID WHERE entityType = $1 FOR UPDATE
2009-07-17 14:10:59 4736 970134 DEBUG: CommitTransactionCommand
2009-07-17 14:10:59 4736 970134 DEBUG: parse <unnamed>: UPDATE
tableEntityID SET nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 DEBUG: StartTransactionCommand
2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 DEBUG: parse tree:
2009-07-17 14:10:59 4736 970134 DETAIL: {QUERY
:commandType 2
:querySource 0
:canSetTag true
:utilityStmt <>
:resultRelation 1
:into <>
:intoOptions <>
:intoOnCommit 0
:intoTableSpaceName <>
:hasAggs false
:hasSubLinks false
:rtable (
{RTE
:alias <>
:eref
{ALIAS
:aliasname tableentityid
:colnames ("entitytype" "nextentityid")
}
:rtekind 0
:relid 16420
:inh true
:inFromCl false
:requiredPerms 6
:checkAsUser 0
}
)
:jointree
{FROMEXPR
:fromlist (
{RANGETBLREF
:rtindex 1
}
)
:quals
{OPEXPR
:opno 98
:opfuncid 0
:opresulttype 16
:opretset false
:args (
{RELABELTYPE
:arg
{VAR
:varno 1
:varattno 1
:vartype 1043
:vartypmod 68
:varlevelsup 0
:varnoold 1
:varoattno 1
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
{RELABELTYPE
:arg
{PARAM
:paramkind 0
:paramid 2
:paramtype 1043
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
)
}
}
:targetList (
{TARGETENTRY
:expr
{FUNCEXPR
:funcid 669
:funcresulttype 1043
:funcretset false
:funcformat 2
:args (
{FUNCEXPR
:funcid 112
:funcresulttype 1043
:funcretset false
:funcformat 2
:args (
{PARAM
:paramkind 0
:paramid 1
:paramtype 23
}
)
}
{CONST
:consttype 23
:constlen 4
:constbyval true
:constisnull false
:constvalue 4 [ -124 0 0 0 ]
}
{CONST
:consttype 16
:constlen 1
:constbyval true
:constisnull false
:constvalue 1 [ 0 0 0 0 ]
}
)
}
:resno 2
:resname nextentityid
:ressortgroupref 0
:resorigtbl 0
:resorigcol 0
:resjunk false
}
)
:returningList <>
:groupClause <>
:havingQual <>
:distinctClause <>
:sortClause <>
:limitOffset <>
:limitCount <>
:rowMarks <>
:setOperations <>
:resultRelations <>
:returningLists <>
}

2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 DEBUG: rewritten parse tree:
2009-07-17 14:10:59 4736 970134 DETAIL: (
{QUERY
:commandType 2
:querySource 0
:canSetTag true
:utilityStmt <>
:resultRelation 1
:into <>
:intoOptions <>
:intoOnCommit 0
:intoTableSpaceName <>
:hasAggs false
:hasSubLinks false
:rtable (
{RTE
:alias <>
:eref
{ALIAS
:aliasname tableentityid
:colnames ("entitytype" "nextentityid")
}
:rtekind 0
:relid 16420
:inh true
:inFromCl false
:requiredPerms 6
:checkAsUser 0
}
)
:jointree
{FROMEXPR
:fromlist (
{RANGETBLREF
:rtindex 1
}
)
:quals
{OPEXPR
:opno 98
:opfuncid 0
:opresulttype 16
:opretset false
:args (
{RELABELTYPE
:arg
{VAR
:varno 1
:varattno 1
:vartype 1043
:vartypmod 68
:varlevelsup 0
:varnoold 1
:varoattno 1
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
{RELABELTYPE
:arg
{PARAM
:paramkind 0
:paramid 2
:paramtype 1043
}
:resulttype 25
:resulttypmod -1
:relabelformat 2
}
)
}
}
:targetList (
{TARGETENTRY
:expr
{FUNCEXPR
:funcid 669
:funcresulttype 1043
:funcretset false
:funcformat 2
:args (
{FUNCEXPR
:funcid 112
:funcresulttype 1043
:funcretset false
:funcformat 2
:args (
{PARAM
:paramkind 0
:paramid 1
:paramtype 23
}
)
}
{CONST
:consttype 23
:constlen 4
:constbyval true
:constisnull false
:constvalue 4 [ -124 0 0 0 ]
}
{CONST
:consttype 16
:constlen 1
:constbyval true
:constisnull false
:constvalue 1 [ 0 0 0 0 ]
}
)
}
:resno 2
:resname nextentityid
:ressortgroupref 0
:resorigtbl 0
:resorigcol 0
:resjunk false
}
)
:returningList <>
:groupClause <>
:havingQual <>
:distinctClause <>
:sortClause <>
:limitOffset <>
:limitCount <>
:rowMarks <>
:setOperations <>
:resultRelations <>
:returningLists <>
}
)

2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 LOG: duration: 0.000 ms
2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 DEBUG: bind <unnamed> to <unnamed>
2009-07-17 14:10:59 4736 970134 DEBUG: plan:
2009-07-17 14:10:59 4736 970134 DETAIL: {SEQSCAN
:startup_cost 0.00
:total_cost 4.05
:plan_rows 1
:plan_width 17
:targetlist (
{TARGETENTRY
:expr
{VAR
:varno 1
:varattno 1
:vartype 1043
:vartypmod 68
:varlevelsup 0
:varnoold 1
:varoattno 1
}
:resno 1
:resname entitytype
:ressortgroupref 0
:resorigtbl 0
:resorigcol 0
:resjunk false
}
{TARGETENTRY
:expr
{CONST
:consttype 1043
:constlen -1
:constbyval false
:constisnull false
:constvalue 7 [ 7 0 0 0 51 48 53 ]
}
:resno 2
:resname nextentityid
:ressortgroupref 0
:resorigtbl 0
:resorigcol 0
:resjunk false
}
{TARGETENTRY
:expr
{VAR
:varno 1
:varattno -1
:vartype 27
:vartypmod -1
:varlevelsup 0
:varnoold 1
:varoattno -1
}
:resno 3
:resname ctid
:ressortgroupref 0
:resorigtbl 0
:resorigcol 0
:resjunk true
}
)
:qual (
{OPEXPR
:opno 98
:opfuncid 67
:opresulttype 16
:opretset false
:args (
{RELABELTYPE
:arg
{VAR
:varno 1
:varattno 1
:vartype 1043
:vartypmod 68
:varlevelsup 0
:varnoold 1
:varoattno 1
}
:resulttype 25
:resulttypmod -1
:relabelformat 0
}
{CONST
:consttype 25
:constlen -1
:constbyval false
:constisnull false
:constvalue 10 [ 10 0 0 0 119 105 122 97 114 100 ]
}
)
}
)
:lefttree <>
:righttree <>
:initPlan <>
:extParam (b)
:allParam (b)
:nParamExec 0
:scanrelid 1
}

2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 LOG: duration: 0.000 ms
2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 DEBUG: ProcessQuery
2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 LOG: duration: 0.000 ms
2009-07-17 14:10:59 4736 970134 STATEMENT: UPDATE tableEntityID SET
nextEntityID = $1 WHERE entityType = $2
2009-07-17 14:10:59 4736 970134 DEBUG: CommitTransactionCommand

-----Original Message-----
From: Raji Sridar (raji)
Sent: Friday, July 17, 2009 9:48 AM
To: 'Greg Smith'
Cc: pgsql-general(at)postgresql(dot)org
Subject: RE: [GENERAL] Concurrency issue under very heay loads

Thanks for everyone's inputs and here is an update on the issue:
The problem source is that autocommit is not getting unset.
The code does the following ( and source code or copyright does not
belong to Cisco):
. unsets autocommit
. starts transaction
. SQL for select for update....
. SQL for update next sequence number
. Commits transaction
The problem is in unsetting auto commit. Since this runs inside an Jboss
app server/EJB environment, this becomes a no-op and hence the ACIDity
across the select for update and update. We are using postgres 8.2.12 on
Windows with JDBC driver 8.2-506.
Thanks
Raji
-----Original Message-----
From: Greg Smith [mailto:gsmith(at)gregsmith(dot)com]
Sent: Thursday, July 16, 2009 2:03 PM
To: Raji Sridar (raji)
Cc: pgsql-general(at)postgresql(dot)org
Subject: Re: [GENERAL] Concurrency issue under very heay loads

On Wed, 15 Jul 2009, Raji Sridar (raji) wrote:

> When multiple clients are concurrently accessing this table and
> updating it, under extermely heavy loads in the system (stress
> testing), we find that the same order number is being generated for
multiple clients.

The only clean way to generate sequence numbers without needing to worry
about duplicates is using nextval:
http://www.postgresql.org/docs/current/static/functions-sequence.html

If you're trying to duplicate that logic in your own code, there's
probably a subtle race condition in your implementation that is causing
the bug.

If you had two calls to nextval from different clients get the same
value returned, that might be a PostgreSQL bug. Given how much that
code gets tested, the more likely case is that there's something to
tweak in your application instead. I would advise starting with the
presumption it's an issue in your app rather than on the server side of
things.

P.S. Posting the same question to two lists here is frowned upon;
pgsql-general is the right one for a question like this.

--
* Greg Smith gsmith(at)gregsmith(dot)com http://www.gregsmith.com Baltimore, MD