Thread: ERROR: canceling query due to user request
I started with this issue on the pgsql-jdbc list, but was assured that this could not be a bug in the JDBC driver -- it iseither a bug in the configuration or runtime environment or it is a server-side bug. This list seemed like the logicalnext step. We have seen this behavior in 8.0.3 with the 311 JDBC driver. Today I tested with the latest snapshot of the 8.1 developmentcode and the tip of the JDBC driver code from the root. It still happens. The environment for the latest test is: SuSE Linux 9.3 (i586) 2.6.11.4-21.8-smp #1 SMP Tue Jul 19 12:42:37 UTC 2005 Dual Xeon Disk on 7 spindle RAID 5 via SAN All access through JDBC connections. A single thread accessing the database. A connection pool in use -- the thread may grab a different connection each time. No other process concurrently executing against the database. Happens with or without autovacuum running. Failures have also occured on Windows 2000 and Windows XP servers with local hard drives. Xeons in all cases. The software involved "optimistically" tries to do a series of inserts, updates, and/or deletes in a single database transaction. If an exception occurs (for example an insert of a row which already exists) or an update affects zero rows,the transaction is rolled back and the operations are attempted in "cautious" mode -- a commit after each insert updateor delete of a single row. The client is running full out, with a steady supply of ready-to-go requests. Client CPU seems to be the bottleneck, ratherthan anything on the database server hardware. We are only seeing this problem in "cautious" mode -- a database transactionhas been rolled back and we're committing each statement as we go. If we run the same set of data multiple times, the error occurs on different requests each time, indicating it is not datadependent. If we turn on logging at the JDBC driver level, it never happens, indicating that it is timing sensitive. We've never seen it while stepping through the debugger, but since it seems to happen randomly once every fewthousand requests, that would be a unlikely anyway. The error is manifest by this message and stack trace: org.postgresql.util.PSQLException: ERROR: canceling query due to user request at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1499) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1284) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:175) at org.postgresql.jdbc2.AbstractJdbc2Connection.executeTransactionCommand(AbstractJdbc2Connection.java:617) at org.postgresql.jdbc2.AbstractJdbc2Connection.commit(AbstractJdbc2Connection.java:637) at (our application code) There is no method in the JDBC interface to cancel a commit from the client side, and there is nothing in the client codewhich is trying to do so. There are no processes running on the server except services from the SuSE install and theprocesses started by pg_ctl start. We tried setting the ulimit of everything to unlimited, where allowed. We set the open files limit to 4096. These ulimitchanges had no affect on the problem. Does anyone have any ideas on a possible cause, or any diagnostic steps we should take? Thanks, -Kevin
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > org.postgresql.util.PSQLException: ERROR: canceling query due to user request The only possible trigger of that message is a SIGINT sent to the backend. Now the backend will SIGINT itself if a statement timeout expires, so one possibility is that you have statement_timeout set and it's getting exceeded. Otherwise you need to be looking for external causes. regards, tom lane
Thanks, Tom. The statement_timeout setting was also raised on the JDBC list, and has been checked -- there is nothing setting statement_timeout. The connection shows this value at zero. None of our code contains anything PostgreSQL specific, so thereis nothing in our framework or applications that would be aware of the "set statement_timeout" command to be able toissue it. I created the database instance, the user and the database, and have not set this as a default anywhere. Regarding the possibility that a ulimit setting is sending the signal, I am using "su" to set user id to root, issuing theulimit statements to set everything unlimited or very high, then using "su" to set user id to postgres. At that pointthe settings from root still show. Then I'm starting postgres using pg_ctl. Is there any reason the ulimit settingswould not carry through with this approach? Is there a better way to do it? Other than that, what external causes might be at fault when I have both Windows machines and Linux machines which have nothinginstalled but the operating system and PostgreSQL? The only ulimit settings I couldn't set to "unlimited" were pipesize and open files. Is there any chance that the error/rollback path in the code is leaking open files on the server? Is there anything I should run during the test to watch for potential resource exhaustion? -Kevin >>> Tom Lane <tgl@sss.pgh.pa.us> 09/12/05 5:39 PM >>> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > org.postgresql.util.PSQLException: ERROR: canceling query due to user request The only possible trigger of that message is a SIGINT sent to the backend. Now the backend will SIGINT itself if a statement timeout expires, so one possibility is that you have statement_timeout set and it's getting exceeded. Otherwise you need to be looking for external causes. regards, tom lane
One more thought -- I keep coming back to the fact that when we turn on logging in the JDBC driver on the client side, theproblem does not occur. The only possible reason I can see for this having any affect on the problem is the small delayintroduced by the synchronous logging. Since this is only showing up on commit of a database transaction which followsclose on the heels of a rollback on the same connection, is there any chance that there is some very small "settlingtime" needed for a rollback, and we're sometimes getting in ahead of this? -Kevin >>> Tom Lane <tgl@sss.pgh.pa.us> 09/12/05 5:39 PM >>> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > org.postgresql.util.PSQLException: ERROR: canceling query due to user request The only possible trigger of that message is a SIGINT sent to the backend. Now the backend will SIGINT itself if a statement timeout expires, so one possibility is that you have statement_timeout set and it's getting exceeded. Otherwise you need to be looking for external causes. regards, tom lane
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > One more thought -- I keep coming back to the fact that when we turn > on logging in the JDBC driver on the client side, the problem does not > occur. The only possible reason I can see for this having any affect > on the problem is the small delay introduced by the synchronous > logging. Since this is only showing up on commit of a database > transaction which follows close on the heels of a rollback on the same > connection, is there any chance that there is some very small > "settling time" needed for a rollback, and we're sometimes getting in > ahead of this? (1) No. (2) Even if we posit the existence of such a serious bug as that, it wouldn't explain how control gets to the SIGINT response code. regards, tom lane
I'm having a really hard time coming up with theories about the cause or things to check. We ran the test again with logging to disk, and it didn't happen in an hour of testing. The logging boosted the average run time of the series of database modificates we attempt as a single transaction from 44 ms to 58 ms. We logged to a dummy PrintWriter, which just returned to driver code without doing anything, and the time went to 50 ms. We got our first error after 9 minutes with that configuration. The only thing running on the server is the postgres back end. It would be hard to imagine something outside of the postgres software itself which would be able to send the signal only when a rollback occurred. Can you think of anything which could be coming through the protocol stream which would cause this signal during the commit after a rollback? About the only other thing I can think to do is to try to come up with a RAM-based PrintWriter to keep a rolling buffer of JDBC logging which it would dump when we get the error. Since a PrintWriter which did absolutely nothing was right on the edge of blocking the problem, I'm skeptical that adding even that much will allow the problem to show. I welcome all suggestions on what to try or what to monitor. -Kevin >>> Tom Lane <tgl@sss.pgh.pa.us> 09/13/05 11:31 AM >>> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > One more thought -- I keep coming back to the fact that when we turn > on logging in the JDBC driver on the client side, the problem does not > occur. The only possible reason I can see for this having any affect > on the problem is the small delay introduced by the synchronous > logging. Since this is only showing up on commit of a database > transaction which follows close on the heels of a rollback on the same > connection, is there any chance that there is some very small > "settling time" needed for a rollback, and we're sometimes getting in > ahead of this? (1) No. (2) Even if we posit the existence of such a serious bug as that, it wouldn't explain how control gets to the SIGINT response code. regards, tom lane
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > I'm having a really hard time coming up with theories about the cause > or things to check. Have you tried strace'ing the backend process to see if you can see a signal being delivered to it? regards, tom lane
Thanks, Tom. An excellent suggestion. (This 50 year old dog has today learned a new trick.) There is good news and bad news. The good news is that I found the cause, and we can keep this from happening with a change on our end. The bad news is that I think it also points to a backend bug, although not as serious as the potential (hypothetical) one I was asking about earlier. For the record (and the benefit of anyone with similar problems who may search the archives), I got the connection pool set up, and found the pids for the connection processes like this: # ps aux|grep postgres postgres 18307 0.0 0.0 3052 1100 pts/0 S Sep09 0:00 su postgres postgres 18308 0.0 0.0 3408 1828 pts/0 S+ Sep09 0:00 bash postgres 15463 0.0 0.1 89508 3852 pts/0 S 10:09 0:05 /usr/local/pgsql/bin/postmaster -D /var/pgsql/data postgres 15466 0.0 4.0 89652 83004 pts/0 S 10:09 0:00 postgres: writer process postgres 15467 0.0 0.1 7052 2796 pts/0 S 10:09 0:02 postgres: stats buffer process postgres 15468 0.0 0.0 6388 1996 pts/0 S 10:09 0:03 postgres: stats collector process postgres 926 0.0 0.3 90484 7576 pts/0 S 14:34 0:00 postgres: dtr dtr 165.219.88.77(4436) idle postgres 927 0.0 0.2 89956 4684 pts/0 S 14:34 0:00 postgres: dtr dtr 165.219.88.77(4437) idle postgres 928 3.0 1.1 90404 23764 pts/0 S 14:34 0:07 postgres: dtr dtr 165.219.88.77(4438) idle postgres 929 2.7 1.1 90468 23260 pts/0 S 14:34 0:07 postgres: dtr dtr 165.219.88.77(4439) idle root 935 0.0 0.0 1796 648 pts/2 S+ 14:38 0:00 grep postgres I then established an strace session for each connection like this: strace -tt -o strace.926 -p 926 Other flags may have been useful, but strace is new to me, so I took the route I was sure I understood. I ran until we got an error, which involved running through 7,278 transactions. I used Ctrl+C to stop each strace and searched the results for SIGINT. There were 1,799 of them. They always came in a set of lines like this: 13:59:19.625498 recv(7, "P\0\0\0Y\0SELECT lcmtr.\"relationName"..., 8192, 0) = 125 13:59:19.625976 _llseek(32, 0, [0], SEEK_END) = 0 13:59:19.626057 _llseek(33, 0, [8192], SEEK_END) = 0 13:59:19.626159 _llseek(32, 0, [0], SEEK_END) = 0 13:59:19.626257 send(7, "1\0\0\0\0042\0\0\0\4T\0\0\0D\0\2relationName\0\0\0"..., 97, 0) = 97 13:59:19.626352 recv(7, 0x82b1000, 8192, 0) = ? ERESTARTSYS (To be restarted) 13:59:19.628477 --- SIGINT (Interrupt) @ 0 (0) --- 13:59:19.628559 sigreturn() = ? (mask now []) The SELECT statement was easy to find, and it became clear that a programmer had code which was incorrectly canceling a JDBC Statement after reaching the end of the (empty) ResultSet. One time out of 1,799 this was causing the error we were seeing on the subsequent commit, which strikes me as a bug. We've already changed the offending code to avoid the invocation of the Statement.cancel method. Not that it merits high priority, but it might make sense for PostgreSQL to behave more consistently on a commit when a statement within the database transaction has been canceled. There currently is a race condition where if the commit comes fast enough after the Statement.cancel, it receives the error which is the subject of this thread. -Kevin >>> Tom Lane <tgl@sss.pgh.pa.us> 09/13/05 1:18 PM >>> "Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > I'm having a really hard time coming up with theories about the cause > or things to check. Have you tried strace'ing the backend process to see if you can see a signal being delivered to it? regards, tom lane
"Kevin Grittner" <Kevin.Grittner@wicourts.gov> writes: > The SELECT statement was easy to find, and it became clear that a > programmer had code which was incorrectly canceling a JDBC > Statement after reaching the end of the (empty) ResultSet. One > time out of 1,799 this was causing the error we were seeing on > the subsequent commit, which strikes me as a bug. > We've already changed the offending code to avoid the invocation > of the Statement.cancel method. Not that it merits high priority, but > it might make sense for PostgreSQL to behave more consistently on > a commit when a statement within the database transaction has been > canceled. There currently is a race condition where if the commit > comes fast enough after the Statement.cancel, it receives the error > which is the subject of this thread. Yeah. The Query Cancel protocol has a potential race condition in it: the cancel request is not synchronous with respect to your existing connection (it's actually sent over a different connection). If you try to send another command immediately, it's possible that the new command gets to the backend before the cancel signal does, and then the cancel zaps your new command instead of the one you intended. This has been discussed before (try the pgsql-jdbc list archives). I believe we concluded that an appropriate fix was to not consider the cancel request "done" until the client sees the separate connection dropped by the postmaster. libpq's cancel functions wait for that to happen, and I thought that JDBC had been fixed as well --- maybe you are using an old driver version? Of course, if the internal threading in your app is such that you might issue another command before the Statement.cancel method finishes, then it's your own bug. regards, tom lane
Tom Lane wrote: > This has been discussed before (try the pgsql-jdbc list archives). > I believe we concluded that an appropriate fix was to not consider the > cancel request "done" until the client sees the separate connection > dropped by the postmaster. libpq's cancel functions wait for that to > happen, and I thought that JDBC had been fixed as well --- maybe you are > using an old driver version? I thought this got done too, but looking at the current JDBC driver code I don't see it.. -O