Disk quota JDBC throwing deadlock errors

[emilzse]

We have configured quota store as JDBC into PostgreSQL database.

When there is some load we are experiencing that it is throwing deadlock errors (also on single node).

Is there anyone else having this issues?

I have found this in code that i guess was supposed to handle this issue:

// sort the payloads by page id as a deadlock avoidance measure, out
// of order updates may result in deadlock with the addHitsAndSetAccessTime method
List<PageStatsPayload> sorted = sortPayloads(statsUpdates);

See stacktrace below:

2016-12-20 11:47:06,789 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] org.geowebcache.diskquota.jdbc.ParametricDataAccessException: Failed to execute statement INSERT INTO gwc.TILEPAGE SELECT :key, :tileSetId, :pageZ, :pageX, :pageY, :creationTime, :frequencyOfUse, :lastAccessTime, :fillFactor, :numHits WHERE NOT EXISTS(SELECT 1 FROM gwc.TILEPAGE WHERE KEY = :key) with params: {numHits=0, lastAccessTime=24616067, creationTime=24616067, tileSetId=layer_xxx#EPSG:4326#image/png, frequencyOfUse=0.0, pageZ=6, pageY=2, key=layer_xxx#EPSG:4326#image/png@6,2,6, pageX=6, fillFactor=1.0}; nested exception is org.springframework.dao.DeadlockLoserDataAccessException: PreparedStatementCallback; SQL [INSERT INTO gwc.TILEPAGE SELECT ?, ?, ?, ?, ?, ?, ?, ?, ?, ? WHERE NOT EXISTS(SELECT 1 FROM gwc.TILEPAGE WHERE KEY = ?)]; ERROR: deadlock detected
Detail: Process 14399 waits for ShareLock on transaction 237467563; blocked by process 14398.
Process 14398 waits for ShareLock on transaction 237467562; blocked by process 14399.
Hint: See server log for query details.; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected
Detail: Process 14399 waits for ShareLock on transaction 237467563; blocked by process 14398.
Process 14398 waits for ShareLock on transaction 237467562; blocked by process 14399.
Hint: See server log for query details.
2016-12-20 11:47:06,790 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.jdbc.SimpleJdbcTemplate.update(SimpleJdbcTemplate.java:70)
2016-12-20 11:47:06,791 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.jdbc.JDBCQuotaStore.createNewPageStats(JDBCQuotaStore.java:608)
2016-12-20 11:47:06,792 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.jdbc.JDBCQuotaStore.access$400(JDBCQuotaStore.java:69)
2016-12-20 11:47:06,794 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.jdbc.JDBCQuotaStore$9.upsertTilePageFillFactor(JDBCQuotaStore.java:522)
2016-12-20 11:47:06,797 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.jdbc.JDBCQuotaStore$9.doInTransactionWithoutResult(JDBCQuotaStore.java:463)
2016-12-20 11:47:06,800 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:34)
2016-12-20 11:47:06,805 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
2016-12-20 11:47:06,808 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.jdbc.JDBCQuotaStore.addToQuotaAndTileCounts(JDBCQuotaStore.java:451)
2016-12-20 11:47:06,811 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.QueuedQuotaUpdatesConsumer.commit(QueuedQuotaUpdatesConsumer.java:312)
2016-12-20 11:47:06,811 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.QueuedQuotaUpdatesConsumer.checkAggregatedTimeout(QueuedQuotaUpdatesConsumer.java:293)
2016-12-20 11:47:06,897 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.QueuedQuotaUpdatesConsumer.checkAggregatedTimeouts(QueuedQuotaUpdatesConsumer.java:250)
2016-12-20 11:47:06,904 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.QueuedQuotaUpdatesConsumer.call(QueuedQuotaUpdatesConsumer.java:198)
2016-12-20 11:47:06,933 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at org.geowebcache.diskquota.QueuedQuotaUpdatesConsumer.call(QueuedQuotaUpdatesConsumer.java:23)
2016-12-20 11:47:06,940 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
2016-12-20 11:47:06,940 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
2016-12-20 11:47:06,948 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
2016-12-20 11:47:06,951 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] at java.lang.Thread.run(Thread.java:745)
2016-12-20 11:47:06,993 ERROR (GWC DiskQuota Updates Gathering Thread-2)[STDERR] Caused by: org.springframework.dao.DeadlockLoserDataAccessException: PreparedStatementCallback; SQL [INSERT INTO gwc.TILEPAGE SELECT ?, ?, ?, ?, ?, ?, ?, ?, ?, ? WHERE NOT EXISTS(SELECT 1 FROM gwc.TILEPAGE WHERE KEY = ?)]; ERROR: deadlock detected
Detail: Process 14399 waits for ShareLock on transaction 237467563; blocked by process 14398.
Process 14398 waits for ShareLock on transaction 237467562; blocked by process 14399.
Hint: See server log for query details.; nested exception is org.postgresql.util.PSQLException: ERROR: deadlock detected
Detail: Process 14399 waits for ShareLock on transaction 237467563; blocked by process 14398.
Process 14398 waits for ShareLock on transaction 237467562; blocked by process 14399.
Hint: See server log for query details.

[aaime]

See here: https://osgeo-org.atlassian.net/browse/GEOS-7018
Happened only once, never had the time to look into it.

[emilzse]

Thank you for reply. It seems to happen on regular basis in our production environment.

[aaime]

Looks like you have good incentive to fix it then ;-)

[rajanski]

We have similar behaviour when using the in-process db (the default setting for the disk quota db)

[aaime]

If a ticket is urgent for you and not moving, you can also check http://geoserver.org/comm/

[petersmythe]

+1 I have also observed this under load. Temporary workaround is to set GWC_DISKQUOTA_DISABLED=true (just disabling tile truncation in the GUI "Enable disk quota" off is not sufficient).

[aaime]

@petersmythe do you see it with geoserver 3 too? @groldan made changes that could help recently, see for example
#1530