Temos um projeto do Grails que é executado por trás de um balanceador de carga. Existem três instâncias do aplicativo Grails em execução no servidor (usando instâncias separadas do Tomcat). Cada instância tem seu próprio índice pesquisável. Como os índices são separados, a atualização automática não é suficiente para manter o índice consistente entre as instâncias do aplicativo. Devido a isso, desativamos o espelhamento de índice pesquisável e as atualizações no índice são feitas manualmente em um trabalho de quartzo agendado. De acordo com o nosso entendimento, nenhuma outra parte do aplicativo deve modificar o índice.

O trabalho de quartzo é executado uma vez por minuto e verifica, a partir do banco de dados, quais linhas foram atualizadas pelo aplicativo e re-indexa esses objetos. O trabalho também verifica se o mesmo trabalho já está em execução, por isso não faz nenhuma indexação concorrente. O aplicativo é executado bem por algumas horas após a inicialização e, de repente, quando o trabalho é iniciado, LockObtainFailedException é lançado:

22.10.2012 11:20:40 [xxxx.ReindexJob] ERROR Não foi possível atualizar o índice pesquisável, classe org.compass.core.engine.SearchEngineException: Falha ao abrir o gravador do subíndice [produto]; exceção aninhada é org.apache.lucene.store.LockObtainFailedException: Bloquear obter expirou: SimpleFSLock@/home/xxx/tomcat/searchable-index/index/product/lucene-a7bbc72a49512284f5ac54f5d7d32849-write.lock

De acordo com o log da última vez em que o trabalho foi executado, a nova indexação foi feita sem erros e o trabalho foi concluído com êxito. Ainda assim, desta vez a operação de re-indexação lança a exceção de bloqueio, como se a operação anterior estivesse inacabada e o bloqueio não tivesse sido liberado. O bloqueio não será liberado até que o aplicativo seja reiniciado.

Tentamos resolver o problema abrindo manualmente o índice bloqueado, o que causa a impressão do seguinte erro no log:

22.10.2012 11:21:30 [manager.IndexWritersManager] ERRO Estado ilegal, marcando um index writer como aberto, enquanto outro está marcado como aberto para sub index [product]

Depois disso, o trabalho parece estar funcionando corretamente e não fica preso novamente em um estado bloqueado. No entanto, isso faz com que o aplicativo use constantemente 100% do recurso da CPU. Abaixo está uma versão resumida do código de trabalho de quartzo.

Qualquer ajuda seria apreciada para resolver o problema, obrigado antecipadamente.

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

Com base em amostras de CPU JMX, parece que a Compass está fazendo algum agendamento nos bastidores. A partir de amostras de CPU de 1 minuto, parece que há poucas coisas diferentes quando as instâncias normal e 100% da CPU são comparadas:

org.apache.lucene.index.IndexWriter.doWait () está usando a maior parte do tempo da CPU.Bússola Scheduled Executor Thread é mostrado na lista de discussão, isso não foi visto em uma situação normal.Um executor de bússola Thread está fazendo commitMerge, em uma situação normal nenhum desses segmentos estava fazendo commitMerge.