Wir haben ein Grails-Projekt, das hinter einem Load Balancer ausgeführt wird. Auf dem Server werden drei Instanzen der Grails-Anwendung ausgeführt (wobei separate Tomcat-Instanzen verwendet werden). Jede Instanz verfügt über einen eigenen durchsuchbaren Index. Da die Indizes getrennt sind, reicht die automatische Aktualisierung nicht aus, um den Index zwischen den Anwendungsinstanzen konsistent zu halten. Aus diesem Grund haben wir die Spiegelung des durchsuchbaren Index deaktiviert und Aktualisierungen des Index werden manuell in einem geplanten Quarzjob durchgeführt. Nach unserem Verständnis sollte kein anderer Teil der Anwendung den Index ändern.

Der Quarzjob wird einmal pro Minute ausgeführt und überprüft anhand der Datenbank, welche Zeilen von der Anwendung aktualisiert wurden, und indiziert diese Objekte neu. Der Job überprüft auch, ob derselbe Job bereits ausgeführt wird, sodass keine gleichzeitige Indizierung erfolgt. Die Anwendung wird nach dem Start einige Stunden lang problemlos ausgeführt. Wenn der Job dann plötzlich gestartet wird, wird die LockObtainFailedException ausgelöst:

22.10.2012 11:20:40 [xxxx.ReindexJob] ERROR Durchsuchbarer Index konnte nicht aktualisiert werden, Klasse org.compass.core.engine.SearchEngineException: Writer für Subindex [Produkt] konnte nicht geöffnet werden; Verschachtelte Ausnahme ist org.apache.lucene.store.LockObtainFailedException: Zeitüberschreitung beim Abrufen der Sperre: SimpleFSLock@/home/xxx/tomcat/searchable-index/index/product/lucene-a7bbc72a49512284f5ac54f5d7d32849-write.lock

Laut Protokoll wurde die Neuindizierung beim letzten Ausführen des Jobs fehlerfrei durchgeführt und der Job erfolgreich beendet. Diesmal löst der Neuindexierungsvorgang jedoch die Sperrausnahme aus, als ob der vorherige Vorgang nicht abgeschlossen und die Sperre nicht aufgehoben worden wäre. Die Sperre wird erst nach einem Neustart der Anwendung aufgehoben.

Wir haben versucht, das Problem durch manuelles Öffnen des gesperrten Index zu lösen, wodurch der folgende Fehler im Protokoll ausgegeben wird:

22.10.2012 11:21:30 [manager.IndexWritersManager] ERROR Unzulässiger Status, der einen Indexschreiber als offen markiert, während ein anderer als offen für den Unterindex [Produkt] markiert ist.

Danach scheint der Job korrekt zu funktionieren und bleibt nicht mehr in einem gesperrten Zustand hängen. Dies führt jedoch dazu, dass die Anwendung ständig 100% der CPU-Ressource verwendet. Unten finden Sie eine verkürzte Version des Quarz-Auftragscodes.

Jede Hilfe wäre dankbar, um das Problem zu lösen, danke im Voraus.

class ReindexJob {

def compass
...

static Calendar lastIndexed

static triggers = {
    // Every day every minute (at xx:xx:30), start delay 2 min
    // cronExpression:                           "s  m h D M W [Y]"
    cron name: "ReindexTrigger", cronExpression: "30 * * * * ?", startDelay: 120000
}

def execute() {
    if (ConcurrencyHelper.isLocked(ConcurrencyHelper.Locks.LUCENE_INDEX)) {
        log.error("Search index has been locked, not doing anything.")
        return
    }

    try {
        boolean acquiredLock = ConcurrencyHelper.lock(ConcurrencyHelper.Locks.LUCENE_INDEX, "ReindexJob")
        if (!acquiredLock) {
            log.warn("Could not lock search index, not doing anything.")
            return
        }

        Calendar reindexDate = lastIndexed
        Calendar newReindexDate = Calendar.instance
        if (!reindexDate) {
            reindexDate = Calendar.instance
            reindexDate.add(Calendar.MINUTE, -3)
            lastIndexed = reindexDate
        }

        log.debug("+++ Starting ReindexJob, last indexed ${TextHelper.formatDate("yyyy-MM-dd HH:mm:ss", reindexDate.time)} +++")
        Long start = System.currentTimeMillis()

        String reindexMessage = ""

        // Retrieve the ids of products that have been modified since the job last ran
        String productQuery = "select p.id from Product ..."
        List<Long> productIds = Product.executeQuery(productQuery, ["lastIndexedDate": reindexDate.time, "lastIndexedCalendar": reindexDate])

        if (productIds) {
            reindexMessage += "Found ${productIds.size()} product(s) to reindex. "

            final int BATCH_SIZE = 10
            Long time = TimeHelper.timer {
                for (int inserted = 0; inserted < productIds.size(); inserted += BATCH_SIZE) {
                    log.debug("Indexing from ${inserted + 1} to ${Math.min(inserted + BATCH_SIZE, productIds.size())}: ${productIds.subList(inserted, Math.min(inserted + BATCH_SIZE, productIds.size()))}")
                    Product.reindex(productIds.subList(inserted, Math.min(inserted + BATCH_SIZE, productIds.size())))
                    Thread.sleep(250)
                }
            }

            reindexMessage += " (${time / 1000} s). "
        } else {
            reindexMessage += "No products to reindex. "
        }

        log.debug(reindexMessage)

        // Re-index brands
        Brand.reindex()

        lastIndexed = newReindexDate

        log.debug("+++ Finished ReindexJob (${(System.currentTimeMillis() - start) / 1000} s) +++")
    } catch (Exception e) {
        log.error("Could not update searchable index, ${e.class}: ${e.message}")
        if (e instanceof org.apache.lucene.store.LockObtainFailedException || e instanceof org.compass.core.engine.SearchEngineException) {
            log.info("This is a Lucene index locking exception.")
            for (String subIndex in compass.searchEngineIndexManager.getSubIndexes()) {
                if (compass.searchEngineIndexManager.isLocked(subIndex)) {
                    log.info("Releasing Lucene index lock for sub index ${subIndex}")
                    compass.searchEngineIndexManager.releaseLock(subIndex)
                }
            }
        }
    } finally {
        ConcurrencyHelper.unlock(ConcurrencyHelper.Locks.LUCENE_INDEX, "ReindexJob")
    }
}
}

Basierend auf JMX-CPU-Beispielen scheint es, als würde Compass hinter den Kulissen etwas planen. Ausgehend von 1-minütigen CPU-Beispielen scheint es einige Unterschiede zu geben, wenn normale und 100% -CPU-Instanzen verglichen werden:

org.apache.lucene.index.IndexWriter.doWait () belegt die meiste CPU-Zeit.Der Compass Scheduled Executor-Thread wird in der Thread-Liste angezeigt. Dies war in einer normalen Situation nicht der Fall.Ein Compass Executor-Thread führt commitMerge aus. In einer normalen Situation hat keiner dieser Threads commitMerge ausgeführt.