Page MenuHomePhabricator

Weekly indices are force-merged by curator every day for a week
Closed, DuplicatePublic

Description

This observation came out from an investigation into force-merge performance impact on the cluster. It looks like weekly indices are force-merged every day of their week (offset by two days since this is what we tell curator to wait for). For example ecs-default for week 14 (considering a week starting on Mon that's 2025-03-31 to 2025-04-06)

2025-03-30 12:31:30,846 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.12/_forcemerge?max_num_segments=1 13573.687s
2025-03-31 04:44:41,889 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.12/_forcemerge?max_num_segments=1 14466.217s
2025-03-31 19:15:01,301 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.13/_forcemerge?max_num_segments=1 13420.837s
2025-04-01 06:09:06,921 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.12/_forcemerge?max_num_segments=1 12950.229s
2025-04-01 16:28:23,452 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.13/_forcemerge?max_num_segments=1 12906.148s
2025-04-02 11:11:39,126 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.14/_forcemerge?max_num_segments=1 5213.472s
2025-04-03 08:48:30,390 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.14/_forcemerge?max_num_segments=1 7380.601s
2025-04-04 12:37:49,969 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.14/_forcemerge?max_num_segments=1 9460.734s
2025-04-05 04:05:45,456 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.14/_forcemerge?max_num_segments=1 9917.410s
2025-04-06 12:35:44,066 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.14/_forcemerge?max_num_segments=1 13213.116s
2025-04-07 08:57:15,587 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.14/_forcemerge?max_num_segments=1 14749.986s
2025-04-08 04:22:14,517 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.14/_forcemerge?max_num_segments=1 13124.516s
2025-04-09 05:52:59,575 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.15/_forcemerge?max_num_segments=1 3990.150s

As a side note, the same is true for yearly indices like ecs-alerts though those don't see many writes overall and force-merge takes in the order of 10-20 min

Details

Event Timeline

Change #1136713 had a related patch set uploaded (by Filippo Giunchedi; author: Filippo Giunchedi):

[operations/puppet@production] logstash: restore forcemerge in curator

https://gerrit.wikimedia.org/r/1136713

Change #1136713 merged by Cwhite:

[operations/puppet@production] logstash: restore forcemerge in curator

https://gerrit.wikimedia.org/r/1136713

As expected we're down to force-merge only yearly indices every day, because we still write to them and thus (I'm guessing) there is more than one segment

2025-04-19 01:01:09,841 POST http://127.0.0.1:9200/ecs-alerts-2-1.11.0-7-2025/_forcemerge?max_num_segments=1 [status:200 request:1066.721s]
2025-04-20 01:00:45,415 POST http://127.0.0.1:9200/ecs-alerts-2-1.11.0-7-2025/_forcemerge?max_num_segments=1 [status:200 request:1030.866s]
2025-04-21 01:01:22,463 POST http://127.0.0.1:9200/ecs-alerts-2-1.11.0-7-2025/_forcemerge?max_num_segments=1 [status:200 request:1070.041s]
2025-04-22 01:02:28,874 POST http://127.0.0.1:9200/ecs-alerts-2-1.11.0-7-2025/_forcemerge?max_num_segments=1 [status:200 request:1131.049s]
2025-04-23 01:01:12,958 POST http://127.0.0.1:9200/ecs-alerts-2-1.11.0-7-2025/_forcemerge?max_num_segments=1 [status:200 request:1065.124s]
fgiunchedi changed the task status from Open to Stalled.Apr 23 2025, 9:16 AM

I'm stalling the task, will check back in a few weeks

I have pulled recent curator logs sorted by time https://phabricator.wikimedia.org/P76096 (root@logging-sd1001:~# journalctl -u curator_actions_cluster_wide.service --since -20d | grep POST | cut -d ' ' -f 6- | awk '{print $1 " " $2 " " $6 " " $7 " " $8 " " $9 }')

And sorted by index in https://phabricator.wikimedia.org/P76103

Things I noticed:

  • Some daily indices we end up merging twice on two different days, I'm assuming because the index gets written to, e.g.
2025-05-12 03:38:18,358 POST http://127.0.0.1:9200/logstash-k8s-1-7.0.0-1-2025.04.12/_forcemerge?max_num_segments=1 [status:200 request:6297.126s]
2025-05-13 08:54:41,841 POST http://127.0.0.1:9200/logstash-k8s-1-7.0.0-1-2025.04.12/_forcemerge?max_num_segments=1 [status:200 request:7466.953s]
  • For the same reason I'm assuming, it has happened that "old" weekly indices get forcemerged too
2025-05-07 04:18:15,134 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.15/_forcemerge?max_num_segments=1 [status:200 request:11525.664s]
2025-05-08 02:48:03,980 POST http://127.0.0.1:9200/ecs-default-1-1.11.0-7-2025.15/_forcemerge?max_num_segments=1 [status:200 request:6994.221s]

Week 15 of 2025 is April 7th to April 13th and yet forcemerge happened two days in a row after about a month