don't keep open pgsql transaction when trac is idle

[Radim Kolar]

When trac is idle, postgresql database connection is in midle of transaction status

53878 ?? Is 0:01.46 postgres: trac trac [local] idle in transaction

If trac with low user activity is running on server, this behaviour has nasty system-wide effects.

1. You can't VACUUM DB. You can but no rows are cleaned
2. You can't replicate DB

until transaction is closed. On lowly loaded Trac, it can take days, so it harms other db users. Close transaction while idle please.

[cboos]

Also reported by someone else on the user list: ​googlegroups:trac-users:f73a346b6797578e

I think this might be related to concurrent sync attempts (#4586) failing and left without doing the appropriate rollback.

[cboos]

Forgot to say: if this is indeed the case, then the current 0.10.4dev (r5153) should already fix this.

[Sonic]

Trac is definitively holding on to connections for too long. I get the same problem with Trac 0.10.4 on PosgreSQL 8.2.4. With 3 Trac environments, each as a separate schema in one database, the process list displays a lot of posgresql positions hanging as idle in transaction.

What kind of info can I provide to help solve it?

[kent@…]

Hi. I use Trac 0.9.3+PostgreSQL

I try to understand why my Trac server became too slow.
I found a lot of established connections even when nobody use Trac.
Command ps -aef give such output:

postgres  9709     1  0 Jan09 ?        00:00:01 /usr/bin/postmaster -D /home/postgresql/data
postgres  9782  9709  0 Jan09 ?        00:00:00 postgres: writer process
postgres  9783  9709  0 Jan09 ?        00:00:00 postgres: stats buffer process
postgres  9957  9709  0 12:02 ?        00:00:00 postgres: tracadmin kent 127.0.0.1(34090) idle
postgres 10113  9709  0 12:39 ?        00:00:00 postgres: tracadmin svninfo 127.0.0.1(32960) idle
postgres 10123  9709  0 12:39 ?        00:00:00 postgres: tracadmin svninfo 127.0.0.1(32961) idle
postgres 10378  9709  0 13:44 ?        00:00:00 postgres: tracadmin l-process-draft 127.0.0.1(44468) idle
postgres 10395  9709  0 13:45 ?        00:00:00 postgres: tracadmin lirxca_0_6_4 127.0.0.1(44469) idle
postgres 10404  9709  0 13:45 ?        00:00:00 postgres: tracadmin lirxca_0_6_4 127.0.0.1(44470) idle
postgres 10493  9709  0 13:51 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(33534) idle
postgres 10531  9709  0 13:52 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(33535) idle
postgres 10536  9709  0 13:52 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(33536) idle
postgres 10557  9709  0 13:52 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(33537) idle
postgres 10565  9709  0 13:52 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(33538) idle
postgres 10593  9709  0 14:00 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(53450) idle
postgres 10621  9709  0 14:00 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(53452) idle
postgres 10657  9709  0 14:06 ?        00:00:00 postgres: tracadmin l-process-draft 127.0.0.1(34525) idle
postgres 10676  9709  0 14:07 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(34526) idle
postgres 10687  9709  0 14:07 ?        00:00:00 postgres: tracadmin lirvpn 127.0.0.1(34527) idle

Is it the same trouble as described in this ticket?

P.S.: sorry for my English.

[danimo]

I can still confirm this with a recent version of trac 0.11. This is really nasty, as one runs out of postgres connections very quickly.

[Jennifer Drummond <jenn@…>]

I had r7190 recommended to me as a patch that might help, but unfortunately it's from farther up on trunk and doesn't apply cleanly against 0.11. Anyone feel like tweaking it for backwards compatibility?

[cboos]

That changeset has been ported to branches/0.11-stable, simply upgrade to latest stable from svn (TracDownload#Tracstable).

It will be very appreciated if you report back whether the problem got fixed or not after the upgrade, so that we could eventually close this ticket.

[cboos]

Jonas, I see that t.e.o is running using r7316, how is this doing w.r.t to this issue?
Do you think we can close it now?

[jonas]

Yes I think we can close this for now. I've not seen this on t.e.o for a while now and the new pool should be better at closing unused connections.

[guillaume.smet@…]

Hi,

If it's supposed to be fixed in Trac 0.11.2.1 (and it seems to be from what I read above), the problem is not fixed:
\_ postgres: trac trac 000.000.000.000(53423) idle in transaction
(and we have a lot of other PostgreSQL backends in this state).

It causes a few annoying bugs: sometimes, you update data in Trac and data are not consistent when you browse Trac as you connect to different backends which have different snapshots. Typically, I created new milestones and components and sometimes they appeared in the New ticket form, sometimes not.

I'm not sure that the problem is related to the transaction pool but there are definitely transaction leaks going on.

I don't know the trac code at all so please forgive me if I made obvious mistake:

• I see a lot of commit() and very few rollback() on errors, it's a bit surprising;
• when you set the search path in the backend, you rollback on error but you don't commit on success. If you rollback on error, I suppose a transaction is open and so it should be commited on success.

I attached a patch for the latter problem. It seems to fix the problem here. I'll check the status of our connections in a couple of days.

Any comment?

Trac 0.11.2.1
PostgreSQL 8.3.6
CentOS 5

--
Guillaume

[jonas]

This only applies to environments where a database schema is specified:

Yes, I think you're on to something. by setting search_path in rollback() we also start a new transaction. This isn't such a good idea since this connection is probably going back into the pool and not being used for a while. A commit closes the transaction again (probably without much overhead) and avoids the problem with idle connection.

On the other hand I don't think we'll need to add a cnx.commit() to the constructor since this time we know that the connection will be used right away.

I'll commit the rollback() change to 0.11-stable so that this change makes it into the upcoming 0.11.3 release.

Thanks!

[jonas]

Fixed in [7866] and [7867].

[guillaume.smet@…]

Hi Jonas,

Why don't you need to commit the transaction in the constructor? The set search_path is a commitable operation by itself. I don't think it's necessary to let the transaction open more longer than it should be: there's no point in it and moreover you want to commit it.

Suppose the following case (I don't know if it happens in Trac but it's a real use case):

• You get the connection, you set the search_path but you don't commit
  
• You execute a set of queries and for one reason, you have to rollback
  
• Then your search_path is rollbacked too and other queries are executed on whatever the default search_path is (the set search_path is a rollbackable operation too).
  

Even if this case doesn't happen in Trac for whatever reason, there's no reason to take that risk IMHO as there's really no gain in not committing the set search_path right after it's done (the overhead is really negligible).

By the way, the schema thing of Trac is really a great usage of PostgreSQL schemas. Thanks for that.

I don't know if you'll see this comment if I don't reopen the ticket so I reopen it. Sorry if it's not what I should have done.

--
Guillaume

[jonas]

Yes, I just realized that when I took my shower this morning :) This way is slight more efficient and does not require us to override the rollback method.

On the other hand I don't see how the case you describe could happen with the current code since it always re-sets the search_path directly after a rollback(). But it doesn't matter anyway since setting it once in the constructor is more efficient anyway.

This should be fixed in [7868] and [7869], thanks again!

[guillaume.smet@…]

Yeah, it's better like that.

Thanks for fixing it in 0.11, I must admit I had a hard time when my milestones changed every time I refreshed the page.

--
Guillaume