ロードバランサーの背後で実行される Grails プロジェクトがあります。サーバー上で実行されている Grails アプリケーションの 3 つのインスタンスがあります (個別の Tomcat インスタンスを使用)。各インスタンスには、独自の検索可能なインデックスがあります。インデックスは個別であるため、アプリケーション インスタンス間でインデックスの一貫性を維持するには、自動更新だけでは十分ではありません。このため、検索可能なインデックスのミラーリングを無効にし、インデックスの更新はスケジュールされた Quartz ジョブで手動で行われます。私たちの理解によれば、アプリケーションの他の部分はインデックスを変更すべきではありません。
Quartz ジョブは 1 分に 1 回実行され、アプリケーションによって更新された行をデータベースからチェックし、それらのオブジェクトのインデックスを再作成します。ジョブは、同じジョブが既に実行されているかどうかも確認するため、同時インデックス作成は行われません。アプリケーションは起動後数時間は問題なく動作しますが、ジョブの開始時に突然 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
前回のジョブ実行時のログによると、再インデックスはエラーなく実行され、ジョブは正常に終了しました。それでも、前回の操作が未完了でロックが解除されていないかのように、今回は再インデックス操作によってロック例外がスローされます。アプリケーションを再起動するまでロックは解除されません。
ロックされたインデックスを手動で開くことで問題を解決しようとしましたが、これにより次のエラーがログに出力されました。
22.10.2012 11:21:30 [manager.IndexWritersManager] エラー 不正な状態です。インデックス ライターを開いているとマークしていますが、別のライターはサブ インデックス [製品] に対して開いているとマークされています
この後、ジョブは正しく機能しているように見え、再びロック状態でスタックすることはありません。ただし、これにより、アプリケーションは常に CPU リソースの 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 CPU サンプルに基づくと、Compass は舞台裏で何らかのスケジューリングを行っているようです。1 分間の CPU サンプルから、通常のインスタンスと 100% の CPU インスタンスを比較すると、いくつかの違いがあるように見えます。
- org.apache.lucene.index.IndexWriter.doWait() がほとんどの CPU 時間を使用しています。
- Compass Scheduled Executor スレッドがスレッド リストに表示されますが、これは通常の状況では見られませんでした。
- 1 つの Compass Executor スレッドが commitMerge を実行していますが、通常の状況では、これらのスレッドのいずれも commitMerge を実行していません。