Tenemos un proyecto de Grails que se ejecuta detrás de un equilibrador de carga. Hay tres instancias de la aplicación Grails que se ejecutan en el servidor (usando instancias de Tomcat separadas). Cada instancia tiene su propio índice de búsqueda. Debido a que los índices están separados, la actualización automática no es suficiente para mantener el índice consistente entre las instancias de la aplicación. Debido a esto, hemos deshabilitado la duplicación del índice de búsqueda y las actualizaciones del índice se realizan manualmente en un trabajo de cuarzo programado. Según nuestro entendimiento, ninguna otra parte de la aplicación debe modificar el índice.

El trabajo de cuarzo se ejecuta una vez por minuto y desde la base de datos comprueba qué filas ha actualizado la aplicación y vuelve a indexar esos objetos. El trabajo también comprueba si el mismo trabajo ya se está ejecutando, por lo que no realiza ninguna indexación simultánea. La aplicación se ejecuta bien durante unas pocas horas después del inicio y, de repente, cuando se inicia el trabajo, se lanza la excepción LockObtainFailedException:

22.10.2012 11:20:40 [xxxx.ReindexJob] ERROR No se pudo actualizar el índice de búsqueda, clase org.compass.core.engine.SearchEngineException: no se pudo abrir el escritor para el subíndice [producto]; la excepción anidada es org.apache.lucene.store.LockObtainFailedException: Tiempo de espera de bloqueo agotado: SimpleFSLock@/home/xxx/tomcat/searchable-index/index/product/lucene-a7bbc72a49512284f5ac54f5d7d32849-rite

De acuerdo con el registro, la última vez que se ejecutó el trabajo, se realizó una nueva indexación sin errores y el trabajo se completó con éxito. Aún así, esta vez la operación de volver a indexar arroja la excepción de bloqueo, como si la operación anterior no estuviera terminada y el bloqueo no se hubiera liberado. El bloqueo no se liberará hasta que se reinicie la aplicación.

Intentamos resolver el problema abriendo manualmente el índice bloqueado, lo que hace que se imprima el siguiente error en el registro:

22.10.2012 11:21:30 [manager.IndexWritersManager] ERROR Estado ilegal, que marca un escritor de índice como abierto, mientras que otro está marcado como abierto para un subíndice [producto]

Después de esto, el trabajo parece funcionar correctamente y no se bloquea de nuevo en un estado bloqueado. Sin embargo, esto hace que la aplicación use constantemente el 100% del recurso de la CPU. A continuación se muestra una versión abreviada del código de trabajo de cuarzo.

Cualquier ayuda sería apreciada para resolver el problema, gracias de antemano.

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

Según las muestras de CPU de JMX, parece que Compass está programando algo entre bastidores. A partir de muestras de CPU de 1 minuto, parece que hay algunas cosas diferentes cuando se comparan las instancias normales y del 100% de la CPU:

org.apache.lucene.index.IndexWriter.doWait () usa la mayor parte del tiempo de CPU.Compass Scheduled Executor Thread se muestra en la lista de hilos, esto no se vio en una situación normal.Un subproceso de Compass Executor está haciendo commitMerge, en una situación normal, ninguno de estos hilos estaba haciendo commitMerge.