Site icon CleverTap Tech Blog

The MongoDB Upgrade That Took The Blame

In this post, Karan, a staff engineer at CleverTap, tells us his first hand experience during a database maintenance update, which resulted in two months of larger instances, faster disks, and a failed downgrade – all because a config clean-up dropped one line.

23 January 2025, late at night. Three of us were on a call, downgrading a production MongoDB cluster from 6.0 back to 5.0, and it got stuck.

FCV, the feature compatibility version, decides which version’s data format MongoDB writes. Ours was caught in a transitional state, no longer 6.0 and not yet 5.0. We couldn’t finish going back, and going forward to 7.0 wasn’t an option either. It was neither here nor there, and it felt like a bad dream refusing to end.

To explain how we got there, I have to go back two weeks.

Two Weeks Earlier

Some context first. In January 2025, I was on the Mongo team at CleverTap. I owned everything Mongo-related except the clusters themselves. One of those clusters sat behind our WhatsApp campaigns, and it holds a very large number of collections. That detail matters later.

Three changes went out in the second week of January. We batched everything held over the New Year week into the first release after it, so they all landed together.

I was eager to see my refactor go out, and even more excited about the Coldplay concert in Dubai after a hectic quarter. I flew out on 8 January, the same day the upgrade started, and was away for the first week of what came next.

On 14 January, the day started normally. I was catching my colleagues up on the Dubai trip when someone from the WhatsApp team (the team I’m on now) came to my desk and asked if anything had changed on the Mongo side, because their campaigns were running slow. That was the first I’d heard of it, and I didn’t know how serious it was yet.

It had started on 9 January, the day after I left, when latency on WhatsApp delivery reports went higher than usual.

It was like a mystery case that needed solving. Everyone was looking at the network, because the errors in the service that sends WhatsApp messages were timeouts on outbound HTTP calls:

java.util.concurrent.TimeoutException: Total timeout 15000 ms elapsed
    at org.eclipse.jetty.client.HttpConnection$RequestTimeouts.onExpired(HttpConnection.java:334)
    at org.eclipse.jetty.client.HttpConnection$RequestTimeouts.onExpired(HttpConnection.java:314)
    at org.eclipse.jetty.io.CyclicTimeouts.onTimeoutExpired(CyclicTimeouts.java:110)

The WhatsApp team tried one thing after another on their end. First the provider: its latency was fine. Then a NAT gateway migration that had landed around the same time: also fine.

At the back of my head, I kept wondering whether one of my changes had caused this. My imposter syndrome was in full swing, and I couldn’t get rid of the feeling that it was me. So I started checking my changes on the side. It was slow going. AI agents weren’t in the limelight yet, so I was checking everything by hand.

Later we found out the requests were never sent. The worker threads that sent them also did the Mongo write after each response. Slow writes kept them busy, and after 15 seconds Jetty gave up and called it a timeout.

The graphs had pointed at Mongo all along. For every message, the service calls the WhatsApp provider, then writes the result to Mongo. The provider call hadn’t changed:

The HTTP call to the provider, 1–21 Jan: between ~0.6 and 1.8 s throughout.

The Mongo write had:

Handling the response, which is the Mongo write: ~1 s a day until 8 Jan, then 5–10 s.

On the cluster itself, slow writes went up about 10×, from under 100K per 4 hours to peaks of ~850K on 9 and 11 January, both while I was away.

WhatsApp got its own HTTP client, and that left Mongo as the only suspect. The network chase had taken until 21 January, almost two weeks from when the slowdown started.

Blaming The Upgrade

On 21 January, the Mongo team, the DevOps team and our MongoDB support partner got together. Everyone agreed the upgrade was to blame. The slowness lined up with it, performance can drop after a major upgrade, and going back to 5.0 was the last thing left to try. Our support partner advised against moving forward to 7.0, and suggested trying the downgrade first. Nobody mentioned the config clean-up. It wasn’t in the picture yet.

By now I was sure the upgrade had caused it. But I was sceptical about going back to 5.0, because FCV had already been raised to 6.0.

The Downgrade

I still remember the night we decided to downgrade the cluster to 5.0. That was a challenge in itself. With FCV at 6.0, some of the data being written was already in a format 5.0 couldn’t read. We had our fingers crossed anyway, and started the downgrade outside business hours. It was me, one of my teammates and a DevOps colleague on the call.

Then it got stuck, which is where this post started.

Going forward wasn’t an option either. Upgrading to 7.0 needs FCV at 6.0, and we’d already been advised against it. People were also reporting performance drops after moving from 6.0 to 7.0. And we hadn’t properly tested 7.0 in staging, so moving a live production cluster onto it felt like swapping one unknown for another.

The night ended successfully, after we promoted one of the 6.0 secondaries to primary, added a new 6.0 node to the replica set and bumped FCV back up to 6.0. Successfully meaning we got out of the transitional state and back to the original problem.

One Fix After Another

With no way back to 5.0, we treated it as a 6.0 regression and tried to tune our way out:

Slow writes per 15 minutes on 24 Jan. The eviction tuning went in around 16:35 IST.

Every other day brought news that another fix hadn’t worked. We stopped creating indexes when a campaign was created, since building indexes is heavy work and the cluster had none to spare. The WhatsApp team hardened what they could on their side: slow-query alerts on the WhatsApp collections, no automatic retries on failed WhatsApp queries, and a Redis of their own for WhatsApp events.

With every fix failing, I started looking at my own changes more carefully.

The Villain in My Own Murder Mystery

In late February, it got worse. The cluster stopped responding for 26 minutes.

After that, I went through my changes again, line by line, and this time I found it. My refactor had swapped a plain paginated find on one of the WhatsApp collections for a shared helper that counted every document in it before returning each page. On this cluster, it was running into the 35-minute execution limit.

It was the same feeling you get when you figure out you caused an issue. Like a villain in your own murder mystery.

I reverted it on 26 February at 8pm. I’m still not sure it helped, or whether it played a part in the slowdown. At this point I was just trying to help as much as I could, and the fix went out with a few apologies. Either way, it wasn’t the problem.

Then there was the hourly job. Back in September, I’d added a scheduled job that printed index metrics for every collection in the region, once an hour. On 3 March, we disabled it, and the number of stuck threads in our backend services dropped sharply. That one was mine as well.

By then, people were just tired, and every new issue seemed to trace back to a commit with my name on it. Like a salami attack, one slice at a time.

The Fix

In early March, while still going through the cluster’s diagnostics, our support partner suggested a WiredTiger setting: keep a lot more file handles open, and close idle ones far less often.

storage:
  wiredTiger:
    engineConfig:
      configString: "file_manager=(close_handle_minimum=20000,close_idle_time=600,close_scan_interval=120)"

The same three of us from the downgrade night applied it at 02:00 IST on 6 March. We saw it working the next morning.

The primary around the restart with the new config. Times are UTC, so 20:30 is 02:00 IST. Read and write latency drop from ~1.2 s to almost nothing. Cache and memory drop too, but that’s the restart.

Four days later, there were still no timeouts, no stuck threads and fewer disk spikes.

Then our DevOps colleague compared the new line with the config the cluster had run on 5.0. The same line was there, and it had been there for years. The config clean-up had dropped it, and the upgrade had shipped the clean-up.

It felt good to know the issue was finally over, and even better that it wasn’t my fault.

I sent out a root cause analysis (RCA) with the exact sequence of events, and we called it a day.

Why One Line Mattered

So how does one missing line do all that?

Every collection and every index in MongoDB is its own file, and each open file has a data handle. The WhatsApp cluster had several thousand of them.

WiredTiger runs a sweeper that closes idle handles. Three settings control it:

5.0 default6.0 defaultOur tuned line
close_handle_minimum2502,00020,000
close_idle_time600 s600 s600 s
close_scan_interval10 s10 s120 s

On 5.0, the cluster ran with the tuned line. After the clean-up, it ran on the 6.0 defaults.

The sweeper only closes handles once more than close_handle_minimum are open. With the tuned line, that minimum was 20,000, above the cluster’s file count, so the sweeper never closed anything. Without it, the cluster fell back to the 6.0 default of 2,000. Every 10 seconds, the sweeper was free to close any handle that had been idle for 10 minutes.

Closing a handle isn’t free. It drops that file’s data from the cache, so the next read goes to disk. And with lots of handles open, checkpoints can stall on the schema lock, holding up normal writes.

Two things kept triggering that churn. One was my hourly job, which opened every collection once an hour to print index metrics. On the old config that was harmless, because the handles just stayed open. After the clean-up, every run opened thousands of handles, and about 10 minutes later the sweeper started closing them again, dropping their cached data on the way out. The other was big campaigns. A single campaign could be 30–40M WhatsApp messages, with every result written to the same small part of the cluster. That filled the cache with one slice of the data, while the rest of the collections sat idle long enough to be swept. When they were needed again, their reads went to disk.

This also explains the things that didn’t add up at the time:

We never measured the handle churn directly, so this is the explanation that fits best, not a proof.

Why It Took Two Months

The config change was invisible. It came inside the Docker image the upgrade rolled out, and the image tag only said 5.0 → 6.0.

The one test that could have settled it couldn’t run. Going back to 5.0 got stuck on FCV, because we’d raised it with the upgrade instead of after a burn-in.

Treating the symptoms partly worked, and every small improvement looked like proof that 6.0 was just slower.

And the red herrings had my name on them. Each one pulled attention back to application changes, and away from the config.

Each of these made sense on its own. Together, they added up to two months.

What I Do Differently Now

The file_manager setting now goes out to every MongoDB cluster through one automated config pipeline, with a tuned profile for clusters shaped like this one. The slow-query alerts on the WhatsApp collections stayed, and so did the WhatsApp team’s fixes.

Anything that can go wrong, will go wrong. Or, as Cooper puts it in Interstellar, whatever can happen, will happen. That January, it all did.

Exit mobile version