기록 보관 : Drupal 7 Search Api 일괄처리 오류로 인한 성능의 급격한 저하

저의 개인 홈페이지에 있던 내용을 옮겨 기록하고자 합니다. 제가 게으른 탓에 활용하기 힘들고 유지를 하기에 금전적으로도 낭비다 생각되어 님길 것은 남기고, 버릴 것은 버리고 사이트를 없에기 위함입니다. 기존 내용 그대로 아래와 같이 옮겼습니다.

---

오늘(2022년 9월 24일) 나는 어재 오후부터 지옥을 해마다 나온 듯 하다.

회사에서 유지보수 및 서버 운영을 하고 있는 GCEDClearinghouse 홈페이지가 매우 심학하게 느려지고, 운영사에서도 항의성 전화가 오고 원인을 찾느라고 지금까지 해매고 겨우 원인을 찾아 임시방편이지만 해결했다.

1. htop 명령으로 서버 상태 확인
2. MySQL Slow Query 확인
3. 의심 원인 확인
4. 인터넷 검색
5. 해결

htop 명령으로 서버 상태 확인

와래와 같이 htop 명령을 실행하여 확인해보니 서버 가용 자원이 거의 남아 있지 않다. 서버의 평균 부하율을 보면 거의 300%에 도달해 있고, 메모리도 1GB 정도 밖에 남아 있지 않다. 그 중에서도 mysqld가 최 상위에 있다. 이건 mysql 쿼리 실행으로 시스템에 부하를 주고 있다는 반증이라 생각된다.

htop

MySQL Slow Query 실행 여부

현재 이 서버는 MariaDB 10.1.34를 이용하고 있다. MariaDB는 MySQL 호황되고 심지어 my.conf 파일의 설정이 매우 유사하다. Slow Query 설정은 두 DB 모두 동일하다. 그래서 급하게나마 아래와 같이 설정하고 데이터베이스를 재실행했다.

slow_query_log          = 1
slow_query_log_file     = /var/log/mysql/mariadb-slow.log
long_query_time = 5

그리고 아래와 같은 Slow Query 로그를 확인할 수 있었다.

# User@Host: gced[gced] @ localhost []
# Thread_id: 2348  Schema: gcedclearinghouse_org  QC_hit: No
# Query_time: 32.410811  Lock_time: 0.000109  Rows_sent: 9267660  Rows_examined: 9267660
# Rows_affected: 0
SET timestamp=1663959260;
SELECT t.*
FROM
`search_api_task` t
WHERE  (t.type IN  ('addIndex', 'fieldsUpdated', 'removeIndex', 'deleteItems')) AND (t.server_id = 'inner_solr')
ORDER BY t.id ASC;

의심 원인 확인

위 내용을 보면 쿼리 실행에 걸린 시간이 32초, 평가 대상 레코드 9,267,660건, 전송 레코드 역시 동일한 수로 표시된다. 확인해보니 아래와 같이 search_api_task 테이블에 비정상 데이터가 이렇게나 많이 쌓여 있는 것이다. 아래의 내용은 운영서버의 것은 아니지만 이런 식으로 쌓여 있었다. 운영서버는 이것 보다 엄청 심하다.

mysql> select * from search_api_task limit 10;
+--------+-----------+-------------+--------------------------+------------------------+
| id     | server_id | type        | index_id                 | data                   |
+--------+-----------+-------------+--------------------------+------------------------+
| 532555 | solr      | deleteItems | files_for_download_index | a:1:{i:0;s:5:"11705";} |
| 532556 | solr      | deleteItems | products_index           | a:1:{i:0;s:5:"11673";} |
| 532557 | solr      | deleteItems | files_for_download_index | a:1:{i:0;s:5:"11673";} |
| 532558 | solr      | deleteItems | products_index           | a:1:{i:0;s:5:"11706";} |
| 532559 | solr      | deleteItems | files_for_download_index | a:1:{i:0;s:5:"11706";} |
| 532560 | solr      | deleteItems | products_index           | a:1:{i:0;s:5:"11707";} |
| 532561 | solr      | deleteItems | files_for_download_index | a:1:{i:0;s:5:"11707";} |
| 532562 | solr      | deleteItems | products_index           | a:1:{i:0;s:5:"11708";} |
| 532563 | solr      | deleteItems | files_for_download_index | a:1:{i:0;s:5:"11708";} |
| 532564 | solr      | deleteItems | products_index           | a:1:{i:0;s:5:"11709";} |
+--------+-----------+-------------+--------------------------+------------------------+

이 테이블은 Drupal 기여 모듈인 Search Api 모듈의 검색엔진을 위한 색인작업(일괄처리) 정보를 저장하고 있는 것으로 작업이 끝난 경우 해당 작업정보가 삭제되어야 마땅하지만 그대로 남아 쌓이고 있었던 것이다. 이 모듈의 오류로 생각하고 인터넷을 검색해보니 역시 그렇다.

인터넷 검색

인터넷을 검색해보니 아래의 페이지에 나와 동일한 사례가 나왔다. 이 페이지의 내용을 보면 Search Api 모듈의 오류로 확신하며, 색인 작업 실페로 인해 작업은 중단되고 끝나지 않은 작업정보는 위와 같이 남게 된 것이다. 이렇게 쌓아고 쌓여 시스템에 엄청난 성능 저하를 주고 있었는데, 지금까지 모르고 있었다. Drupal은 원래 좀 무거워서 그런 것이겠거니 생각했다.

https://www.drupal.org/project/search_api/issues/2408727

해결

위에서는 임시 방편으로 해결을 했다고 했는데, 사실 이 방법 밖에 없는 것은 아닌가 하는 생각을 위 사이트 내용을 보고 하게 되었다. 작업이 끝나면 더이상 데이터베이스에 저장된 작업정보는 필요가 없다. 그러므로 문제가 되는 비정상 작업정보를 삭제해도 데이터 무결성에는 영향을 주지 않을 것이다. 모듈의 버그 수정이 가장 최선이겠지만 운영서버를 가지고 수정과 테스트 작업을 하기에는 무리가 있다. 그래서 주기적으로 해당 정보를 지우는 Cron 작업을 하도록 해야겠다.

오늘은 아래와 같이 테이블 데이터 초기화하는 것으로 해결하고 마무리한다.

MariaDB [(none)]> truncate table search_api_task;