У нас есть проект Grails, который работает за балансировщиком нагрузки. На сервере запущено три экземпляра приложения Grails (с использованием отдельных экземпляров Tomcat). Каждый экземпляр имеет свой собственный поисковый индекс. Поскольку индексы являются отдельными, автоматического обновления недостаточно для поддержания согласованности индекса между экземплярами приложения. Из-за этого мы отключили зеркалирование индекса с возможностью поиска и обновления индекса выполняются вручную в запланированном задании кварца. Согласно нашему пониманию, никакая другая часть приложения не должна изменять индекс.

Кварцевое задание запускается раз в минуту, и оно проверяет из базы данных, какие строки были обновлены приложением, и повторно индексирует эти объекты. Задание также проверяет, выполняется ли уже то же задание, поэтому не выполняет одновременную индексацию. Приложение запускается нормально в течение нескольких часов после запуска, а затем внезапно, когда задание запускается, выдается исключение LockObtainFailedException:

22.10.2012 11:20:40 [xxxx.ReindexJob] ОШИБКА Не удалось обновить поисковый индекс, класс org.compass.core.engine.SearchEngineException: не удалось открыть средство записи для подиндекса [product]; вложенное исключение: org.apache.lucene.store.LockObtainFailedException: время ожидания блокировки истекло: SimpleFSLock@/home/xxx/tomcat/searchable-index/index/product/lucene-a7bbc72a49512284f5ac54f5d7d32849-

Согласно журналу в последний раз, когда задание было выполнено, реиндексация была выполнена без ошибок, и задание было успешно завершено. Тем не менее, на этот раз операция переиндексации выдает исключение блокировки, как если бы предыдущая операция была незавершенной, а блокировка не была снята. Блокировка не будет снята, пока приложение не будет перезапущено.

Мы попытались решить проблему, открыв заблокированный индекс вручную, в результате чего в журнал была выведена следующая ошибка:

22.10.2012 11:21:30 [manager.IndexWritersManager] ОШИБКА Недопустимое состояние, помечающий средство записи индекса как открытое, а другое помечено как открытое для подиндекса [product]

После этого работа, кажется, работает правильно и больше не застревает в заблокированном состоянии. Однако это заставляет приложение постоянно использовать 100% ресурсов процессора. Ниже приведена сокращенная версия кварцевого кода работы.

Любая помощь будет оценена, чтобы решить проблему, спасибо заранее.

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

Судя по образцам процессоров JMX, кажется, что Compass негласно планирует. Из 1-минутных выборок ЦП кажется, что при обычном сравнении и 100% -ых экземплярах ЦП мало что отличается:

org.apache.lucene.index.IndexWriter.doWait () использует большую часть процессорного времени.Compass Scheduled Executor Thread отображается в списке потоков, в обычной ситуации такого не было.Один поток Compass Executor выполняет commitMerge, в нормальной ситуации ни один из этих потоков не делал commitMerge.