Deadlock bei paralleler Generierung

[j_mueller]

Hallo eSpirit Community,

seit kurzer Zeit treten während unserers Jobs zur Vollgenerierung hin und wieder Fehler in Form von Deadlocks auf. Dieser Vollgenerierungsjob erzeugt die Webseite in parallelen läufenden Teilaufträgen. Wie im Handbuch beschrieben, haben wir diese so angelegt, dass immer disjunkte Teilbereiche der Webseite in allen Sprachvarianten erzeugt werden.

Wir können uns nicht erklären woher dieser Fehler kommt, denn wir haben schon länger keine Updates mehr eingespielt oder Strukturen im Projekt verändert.

Wie in der Fehlermeldung zu erkennen handelt es sich um ein Deadlock in der über die Datenquellen angebundene externe PostgreSQL-Datenbank. Was ich jedoch nicht verstehe ist, dass bei der Generierung Write-Locks gesetzt werden.

EDIT: Im Log steht ganz klar etwas von 'ACL', daher noch kurz der Hinweis dass das Häckchen 'ACL-Datenbank benutzen' generell in unseren Aufträgen nicht gesetzt ist.

Hier noch die Exception zur Analyse:

ERROR 19.07.2013 00:15:52.476 {seID=236403} (de.espirit.firstspirit.server.scheduler.ScheduleManagerImpl): error in task 'Städte & Kultur' - schedule entry 'Auto-Deploy [ALL]' (id=236403) - java.io.IOException: Database error - com.sleepycat.je.DeadlockException: (JE 3.3.98) Lock expired. Locker 1097681797 1866979388_Queue[DEFAULT]:task 'Städte & Kultur' - schedule entry 'Auto-Deploy [ALL]' (id=236403)_Txn: waited for lock on database=persist#AccessControlDb#de.espirit.firstspirit.acl.File#_acl LockAddr:975760178 node=57 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1374185751112 endTime=1374185752458
Owners: [<LockInfo locker="443154114 1866979386_Queue[DEFAULT]:task 'REST' - schedule entry 'Auto-Deploy [ALL]' (id=236403)_Txn" type="WRITE"/>]
Waiters: []
java.io.IOException: Database error - com.sleepycat.je.DeadlockException: (JE 3.3.98) Lock expired. Locker 1097681797 1866979388_Queue[DEFAULT]:task 'Städte & Kultur' - schedule entry 'Auto-Deploy [ALL]' (id=236403)_Txn: waited for lock on database=persist#AccessControlDb#de.espirit.firstspirit.acl.File#_acl LockAddr:975760178 node=57 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1374185751112 endTime=1374185752458
Owners: [<LockInfo locker="443154114 1866979386_Queue[DEFAULT]:task 'REST' - schedule entry 'Auto-Deploy [ALL]' (id=236403)_Txn" type="WRITE"/>]
Waiters: []
 at de.espirit.common.io.IoUtil.newIoException(IoUtil.java:460)
 at de.espirit.firstspirit.io.AclFileHandleImpl.updateAclFile(AclFileHandleImpl.java:260)
 at de.espirit.firstspirit.io.AclFileHandleImpl$AclUpdateStream.close(AclFileHandleImpl.java:325)
 at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
 at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
 at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
 at de.espirit.common.io.UnsyncedBufferedWriter.close(UnsyncedBufferedWriter.java:257)
 at de.espirit.firstspirit.generate.SiteProduction.render(SiteProduction.java:181)
 at de.espirit.firstspirit.generate.SiteProduction.render(SiteProduction.java:135)
 at de.espirit.firstspirit.generate.SiteProduction.render(SiteProduction.java:138)
 at de.espirit.firstspirit.generate.SiteProduction.start(SiteProduction.java:105)
 at de.espirit.firstspirit.server.scheduler.GenerateTaskExecutor.run(GenerateTaskExecutor.java:235)
 at de.espirit.firstspirit.server.scheduler.ScheduleManagerImpl$TaskCallable.executeLocal(ScheduleManagerImpl.java:2021)
 at de.espirit.firstspirit.server.scheduler.ScheduleManagerImpl$TaskCallable.executeLocal(ScheduleManagerImpl.java:2001)
 at de.espirit.firstspirit.server.scheduler.ScheduleManagerImpl$TaskCallable.call(ScheduleManagerImpl.java:1929)
 at de.espirit.firstspirit.server.ExecutionManagerImpl$ExtendedCallable.call(ExecutionManagerImpl.java:520)
 at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
 at java.util.concurrent.FutureTask.run(FutureTask.java:138)
 at de.espirit.common.util.BoundedExecutorService$RunnableWrapper.run(BoundedExecutorService.java:419)
 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
 at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
 at java.util.concurrent.FutureTask.run(FutureTask.java:138)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
 at java.lang.Thread.run(Thread.java:662)
 at de.espirit.common.util.SuspendableThread.run(SuspendableThread.java:36)
Caused by: com.sleepycat.je.DeadlockException: (JE 3.3.98) Lock expired. Locker 1097681797 1866979388_Queue[DEFAULT]:task 'Städte & Kultur' - schedule entry 'Auto-Deploy [ALL]' (id=236403)_Txn: waited for lock on database=persist#AccessControlDb#de.espirit.firstspirit.acl.File#_acl LockAddr:975760178 node=57 type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1374185751112 endTime=1374185752458
Owners: [<LockInfo locker="443154114 1866979386_Queue[DEFAULT]:task 'REST' - schedule entry 'Auto-Deploy [ALL]' (id=236403)_Txn" type="WRITE"/>]
Waiters: []
 at com.sleepycat.je.txn.LockManager.makeTimeoutMsgInternal(LockManager.java:469)
 at com.sleepycat.je.txn.SyncedLockManager.makeTimeoutMsg(SyncedLockManager.java:77)
 at com.sleepycat.je.txn.LockManager.lock(LockManager.java:278)
 at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:425)
 at com.sleepycat.je.txn.Locker.lock(Locker.java:360)
 at com.sleepycat.je.dbi.CursorImpl.lockDupCountLN(CursorImpl.java:2594)
 at com.sleepycat.je.tree.Tree.insertDuplicate(Tree.java:2731)
 at com.sleepycat.je.tree.Tree.insert(Tree.java:2678)
 at com.sleepycat.je.dbi.CursorImpl.putLN(CursorImpl.java:1052)
 at com.sleepycat.je.dbi.CursorImpl.putNoDupData(CursorImpl.java:1208)
 at com.sleepycat.je.Cursor.putAllowPhantoms(Cursor.java:1470)
 at com.sleepycat.je.Cursor.putNoNotify(Cursor.java:1402)
 at com.sleepycat.je.Cursor.putInternal(Cursor.java:1356)
 at com.sleepycat.je.SecondaryDatabase.insertKey(SecondaryDatabase.java:880)
 at com.sleepycat.je.SecondaryDatabase.updateSecondary(SecondaryDatabase.java:754)
 at com.sleepycat.je.SecondaryTrigger.databaseUpdated(SecondaryTrigger.java:42)
 at com.sleepycat.je.Database.notifyTriggers(Database.java:1735)
 at com.sleepycat.je.Cursor.putInternal(Cursor.java:1364)
 at com.sleepycat.je.Database.putInternal(Database.java:995)
 at com.sleepycat.je.Database.putNoOverwrite(Database.java:930)
 at com.sleepycat.persist.PrimaryIndex.putNoOverwrite(PrimaryIndex.java:476)
 at de.espirit.firstspirit.acl.db.AccessControlDb.createFile(AccessControlDb.java:283)
 at de.espirit.firstspirit.io.AclFileHandleImpl.updateAclFile(AclFileHandleImpl.java:257)
 ... 24 more

Für Hinweise zur Fehlerbehebung bereits vielen Dank!

Schöne Grüße

Julius Müller

[Peter_Jodeleit]

Die Fehlermeldung kommt aus der Berkeley-Instanz der ACL-Datenbank (also nicht aus einer PostgreSQL). Berkeley hat eine Heuristik, die von einem Deadlock ausgeht, sobald ein Lock-Versuch länger als eine definierte Zeitspanne dauert. Dieses Zeitspanne kann man über die fs-server.conf konfigurieren. Da du aber schreibst, das die ACL bei euch eigentlich nicht genutzt werden soll, möchte ich dich bitten, die Aufträge noch mal alle zu kontrollieren. Speziell die Task 'REST' - schedule entry 'Auto-Deploy [ALL]', welche in der Fehlermeldung protokolliert wird. Wenn dort tatsächlich ACL abgehakt ist, stell bitte ein Ticket über unseren Helpdesk ein.