search

clear-code / redmine_full_text_search

Full text search for Redmine
MIT License
61 stars 24 forks source link

Non-unique Error at UpsertTargetJob #81

Closed usk0517 closed 4 years ago

usk0517 commented 4 years ago

チケット更新時にfts_targetsテーブルで一意性制約エラーが発生

一意性制約エラーが発生するのは、fts_targetsテーブルの「source_type_id = 1」のレコードになります。

操作としては、チケットの更新時に発生します。

なお、「full_text_search:synchronize」を実行し、同期対象データが存在しないことを確認しています。

OS：CentOS 7.4 DB：PostgreSQL 11.6 Redmine：4.0.3.stable Ruby version： 2.5.3-p105 Rails version：5.2.2.1 full_text_search：1.0.4 PGroonga:

エラー内容

[2020-03-12 10:51:38 +0900] [ERROR] -- Error performing FullTextSearch::UpdateIssueContentJob (Job ID: ba36130c-672d-4801-9c5b-ad58963ca1c5) from Async(full_text search) in 1.65ms: ActiveRecord::RecordNotFound (Couldn't find Journal with 'id'=28407):
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/core.rb:177:in `find'
/var/lib/redmine/plugins/full_text_search/app/jobs/full_text_search/update_issue_content_job.rb:10:in `perform'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:39:in `block in perform_now'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/i18n-0.7.0/lib/i18n.rb:257:in `with_locale'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `instance_exec'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:26:in `block (4 levels) in <module:Logging>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:25:in `block (3 levels) in <module:Logging>'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:48:in `tag_logger'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:22:in `block (2 levels) in <module:Logging>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `instance_exec'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:38:in `perform_now'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:24:in `block in execute'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/railtie.rb:28:in `block (4 levels) in <class:Railtie>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/reloader.rb:73:in `block in wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/reloader.rb:72:in `wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/railtie.rb:27:in `block (3 levels) in <class:Railtie>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `instance_exec'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:22:in `execute'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/queue_adapters/async_adapter.rb:70:in `perform'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
[2020-03-12 10:51:38 +0900] [ERROR] -- Discarded FullTextSearch::UpdateIssueContentJob due to a ActiveRecord::RecordNotFound. The original exception was nil.
[2020-03-12 10:51:38 +0900] [ERROR] -- Error performing FullTextSearch::UpsertTargetJob (Job ID: abc34fe1-d531-46e3-bb17-5d4bbb6474a4) from Async(full_text_searc h) in 116.51ms: ActiveRecord::RecordNotUnique (PG::UniqueViolation: ERROR: 重複キーが一意性制約"index_fts_targets_on_source_id_and_source_type_id"に違反していま す
DETAIL: キー (source_id, source_type_id)=(28407, 1) はすでに存在します。
: INSERT INTO "fts_targets" ("source_id", "source_type_id", "project_id", "container_id", "container_type_id", "is_private", "last_modified_at", "content", "tag ids") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id"):
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `async_exec_params'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:579:in `block (2 levels) in log'
/usr/local/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:578:in `block in log'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:569:in `log'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:122:in `exec_insert'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:115:in `exec_insert'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:154:in `insert'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:21:in `insert'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:185:in `_insert_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:732:in `_create_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/counter_cache.rb:184:in `_create_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/locking/optimistic.rb:70:in `_create_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/attribute_methods/dirty.rb:140:in `_create_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/callbacks.rb:346:in `block in _create_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:816:in `_run_create_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/callbacks.rb:346:in `_create_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/timestamp.rb:102:in `_create_record'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:703:in `create_or_update'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/callbacks.rb:342:in `block in create_or_update'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/persistence.rb:306:in `save!'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/validations.rb:52:in `save!'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:315:in `block in save!'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:259:in `block in transaction'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/local/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:259:in `transaction'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:212:in `transaction'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/transactions.rb:315:in `save!'
/usr/local/lib/ruby/gems/2.5.0/gems/activerecord-5.2.2.1/lib/active_record/suppressor.rb:48:in `save!'
/var/lib/redmine/plugins/full_text_search/lib/full_text_search/journal_mapper.rb:52:in `upsert_fts_target'
/var/lib/redmine/plugins/full_text_search/app/jobs/full_text_search/upsert_target_job.rb:12:in `perform'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:39:in `block in perform_now'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/i18n-0.7.0/lib/i18n.rb:257:in `with_locale'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `instance_exec'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:26:in `block (4 levels) in <module:Logging>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/notifications.rb:168:in `instrument'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:25:in `block (3 levels) in <module:Logging>'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:48:in `tag_logger'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:22:in `block (2 levels) in <module:Logging>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `instance_exec'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:38:in `perform_now'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:24:in `block in execute'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/railtie.rb:28:in `block (4 levels) in <class:Railtie>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/reloader.rb:73:in `block in wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/execution_wrapper.rb:87:in `wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/reloader.rb:72:in `wrap'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/railtie.rb:27:in `block (3 levels) in <class:Railtie>'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `instance_exec'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/execution.rb:22:in `execute'
/usr/local/lib/ruby/gems/2.5.0/gems/activejob-5.2.2.1/lib/active_job/queue_adapters/async_adapter.rb:70:in `perform'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/usr/local/lib/ruby/gems/2.5.0/gems/concurrent-ruby-1.1.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
kou commented 4 years ago

直してみたつもりなのでmasterを試してみてもらえますか？

usk0517 commented 4 years ago

ちなみに現在の状況が性能に悪影響を及ぼすようなことは考えられますでしょうか？ 15万件程度のチケット数なんですが、検索実行後のカスタムフィールドでの並び替え（一覧画面上で項目をクリック）が 異常に遅くDB上のクエリの実行時間が3分を超えてしまっています Postgreの各種設定のチューニングやanalyze・vacuumをやってもあまり改善されずの状況です

上記内容はこちらで調査中ですし、須藤さんに聞く内容でもないと認識しておりますので full_text_searchの一意制約のエラーが性能に影響を与える可能性があるようなものかという観点で ご教授いただけますでしょうか？

直してみたつもりなのでmasterを試してみてもらえますか？ — You are receiving this because you authored the thread. Reply to this email directly, [a:https://github.com/clear-code/redmine_full_text_search/issues/81#issuecomment-601021402]view it on GitHub, or [a:https://github.com/notifications/unsubscribe-auth/AO3F3GBNJ43QKPZOVKF3ZMTRIG76HANCNFSM4LOA3L3A]unsubscribe.[img:https://github.com/notifications/beacon/AO3F3GD52WSKEEDGB2RJ7JDRIG76HA5CNFSM4LOA3L3KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEPJNXWQ.gif]

kou commented 4 years ago

これは更新時の処理なので検索性能には影響はないです。

性能改善は再現できる環境が手元にないと難しいです。。。 （どの処理が遅いかを調べるとかがやりにくいため。）

usk0517 commented 4 years ago

問題の切り分けができずにいたので 性能に影響がないということがわかればOKです

ありがとうございます

これは更新時の処理なので検索性能には影響はないです。 性能改善は再現できる環境が手元にないと難しいです。。。 （どの処理が遅いかを調べるとかがやりにくいため。） — You are receiving this because you authored the thread. Reply to this email directly, [a:https://github.com/clear-code/redmine_full_text_search/issues/81#issuecomment-601029205]view it on GitHub, or [a:https://github.com/notifications/unsubscribe-auth/AO3F3GFLW7XXD7QXJLJWYGTRIHC2VANCNFSM4LOA3L3A]unsubscribe.[img:https://github.com/notifications/beacon/AO3F3GCEY63J6EAWPKCOQ6TRIHC2VA5CNFSM4LOA3L3KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEPJPUVI.gif]