我们有一个在负载均衡器后面运行的 Grails 项目。服务器上运行着三个 Grails 应用程序实例（使用单独的 Tomcat 实例）。每个实例都有自己的可搜索索引。因为索引是分开的，所以自动更新不足以保持应用程序实例之间的索引一致。因此，我们禁用了可搜索的索引镜像，并且索引的更新是在计划的石英作业中手动完成的。根据我们的理解，应用程序的其他部分不应修改索引。
石英作业每分钟运行一次，它从数据库中检查应用程序更新了哪些行，并重新索引这些对象。该作业还检查同一个作业是否已经在运行，因此它不会执行任何并发索引。应用程序在启动后几个小时内运行良好，然后在作业开始时突然抛出 LockObtainFailedException：
22.10.2012 11:20:40 [xxxx.ReindexJob] 错误无法更新可搜索索引，类 org.compass.core.engine.SearchEngineException：无法打开子索引 [产品] 的编写器；嵌套异常是 org.apache.lucene.store.LockObtainFailedException：锁定获取超时：SimpleFSLock@/home/xxx/tomcat/searchable-index/index/product/lucene-a7bbc72a49512284f5ac54f5d7d32849-write.lock
根据上次执行作业的日志，重新索引已完成，没有任何错误，作业成功完成。尽管如此，这次re-index操作还是抛出了锁定异常，就好像之前的操作没有完成，锁还没有被释放一样。在应用程序重新启动之前，锁不会被释放。
我们尝试通过手动打开锁定的索引来解决问题，导致日志打印如下错误：
22.10.2012 11:21:30 [manager.IndexWritersManager] 错误非法状态，将索引编写器标记为打开，而另一个标记为打开子索引 [产品]
在此之后，工作似乎正常工作并且不会再次陷入锁定状态。但是，这会导致应用程序不断使用 100% 的 CPU 资源。以下是石英作业代码的缩短版本。
任何帮助将不胜感激，以解决问题，在此先感谢。
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 CPU 示例，Compass 似乎在幕后进行了一些调度。从 1 分钟的 CPU 样本来看，在比较正常和 100% CPU 实例时似乎几乎没有什么不同：
- org.apache.lucene.index.IndexWriter.doWait() 正在使用大部分 CPU 时间。
- Compass Scheduled Executor Thread 显示在线程列表中，这在正常情况下是看不到的。
- 一个 Compass Executor 线程正在执行 commitMerge，在正常情况下，这些线程都没有执行 commitMerge。