Indeks przeszukiwalny zostaje zablokowany podczas ręcznej aktualizacji (LockObtainFailedException)

Mamy projekt Grails, który działa za systemem równoważenia obciążenia. Na serwerze działają trzy instancje aplikacji Grails (przy użyciu oddzielnych instancji Tomcat). Każda instancja ma własny indeks wyszukiwania. Ponieważ indeksy są oddzielne, automatyczna aktualizacja nie jest wystarczająca do utrzymania spójności indeksu między instancjami aplikacji. Z tego powodu wyłączyliśmy dublowanie indeksu z możliwością wyszukiwania, a aktualizacje indeksu są wykonywane ręcznie w zaplanowanym zadaniu kwarcowym. Zgodnie z naszym rozumieniem żadna inna część aplikacji nie powinna modyfikować indeksu.

Zadanie kwarcowe działa raz na minutę i sprawdza z bazy danych, które wiersze zostały zaktualizowane przez aplikację i ponownie indeksuje te obiekty. Zadanie sprawdza także, czy to samo zadanie jest już uruchomione, więc nie wykonuje równoczesnego indeksowania. Aplikacja działa dobrze przez kilka godzin po uruchomieniu, a następnie nagle, gdy zadanie jest uruchamiane, zgłaszany jest wyjątek LockObtainFailedException:

22.10.2012 11:20:40 [xxxx.ReindexJob] BŁĄD Nie można zaktualizować przeszukiwalnego indeksu, klasa org.compass.core.engine.SearchEngineException: Nie można otworzyć programu piszącego dla subindeksu [produkt]; zagnieżdżonym wyjątkiem jest org.apache.lucene.store.LockObtainFailedException: blokada uzyska limit czasu: SimpleFSLock@/home/xxx/tomcat/searchable-index/index/product/lucene-a7bbc72a49512284f5ac54f5d7d3284928wr5.lock

Zgodnie z dziennikiem podczas ostatniego wykonania zadania ponowne indeksowanie zostało wykonane bez żadnych błędów i zadanie zakończyło się pomyślnie. Jednak tym razem operacja ponownego indeksowania zgłasza wyjątek blokowania, tak jakby poprzednia operacja była niedokończona, a blokada nie została zwolniona. Blokada nie zostanie zwolniona, dopóki aplikacja nie zostanie ponownie uruchomiona.

Próbowaliśmy rozwiązać problem, ręcznie otwierając zablokowany indeks, co powoduje wydrukowanie następującego błędu w dzienniku:

22.10.2012 11:21:30 [manager.IndexWritersManager] BŁĄD Niedozwolony stan, oznaczenie autora indeksu jako otwartego, podczas gdy inny jest oznaczony jako otwarty dla subindeksu [produkt]

Po tym wydaje się, że zadanie działa poprawnie i nie utknie ponownie w stanie zablokowanym. Jednak powoduje to, że aplikacja stale korzysta ze 100% zasobów procesora. Poniżej znajduje się skrócona wersja kodu pracy kwarcu.

Każda pomoc byłaby doceniana, aby rozwiązać problem, dzięki z góry.

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")
    }
}
}

Na podstawie próbek procesora JMX wydaje się, że Compass planuje trochę za kulisami. Z 1-minutowych próbek procesora wygląda na to, że jest kilka różnych rzeczy, gdy porównuje się normalne i 100% instancje procesora:

org.apache.lucene.index.IndexWriter.doWait () wykorzystuje większość czasu procesora.Wątek Compass Scheduled Executor jest pokazany na liście wątków, nie był widoczny w normalnej sytuacji.Jeden wątek Compass Executor wykonuje commitMerge, w normalnej sytuacji żaden z tych wątków nie robił commitMerge.

questionAnswers(1)

yourAnswerToTheQuestion