Created attachment 36324 [details]
error.log output covering 2-tenths of a second/5k lines

Note: we have a very lengthy and aged httpd.conf file which has cruft from years of fixing defects and adding new options, so it is entirely possible this is some artifact of that. I did try setting up a very simple configuration which just health checks a single non-existent service, and it seems to be well behaved. I can't share the config file as it contains sensitive (and embarrassing) information unfortunately. :)

Replicable also on 39, Windows Server 2012 

It is about health check memory leaks depends on frequency.

To reproduce...
(1) You have to have more than one high freq health check like...
ProxyHCExpr wsOK {%{REQUEST_STATUS} =~ /405|200/}
ProxyHCTemplate X1 hcexpr=wsOK hcmethod=GET hcuri=WHATEVER_WORKS_FOR_YOU_1 hcinterval=5 hcpasses=2 hcfails=1
<Proxy balancer://clusterFxAgregation>
BalancerMember http://127.0.0.1:10179 route=127.0.0.1 retry=0 hctemplate=X1
BalancerMember http://10.115.51.15:10179 status=+H route=10.115.51.15 retry=0 hctemplate=X1
BalancerMember http://10.115.51.27:10179 status=+H route=10.115.51.27 retry=0 hctemplate=X1
</Proxy>

ProxyHCTemplate X2 hcexpr=wsOK hcmethod=GET hcuri=WHATEVER_WORKS_FOR_YOU_2 hcinterval=5 hcpasses=2 hcfails=1
<Proxy balancer://clusterFxAgregation>
BalancerMember http://127.0.0.1:10178 route=127.0.0.1 retry=0 hctemplate=X2
BalancerMember http://10.115.51.15:10178 status=+H route=10.115.51.15 retry=0 hctemplate=X2
BalancerMember http://10.115.51.27:10178 status=+H route=10.115.51.27 retry=0 hctemplate=X2
</Proxy>

here those are defined as two virtual hosts in the same conf

(2) Some nodes must be down. For instance 127.0.0.1 in example above

(3) Observe memory. Leak spead depends on number of defined checks and their freq. With configuration like above and around 20 virtual hosts it should be like 10MB/min

I've spent quite a bit of time over the last few days trying to understand what goes on here. I have reproduced the memory growth on both Windows and Linux with Apache httpd 2.4.46. It doesn't depend on health check failures, though they can affect the timing to make it more likely. (In my testing, I dummied out the actual check in hc_check() and just put in a fixed delay to avoid vagaries of network stuff.)

My conclusion is that it's strongly related to bug #62318 (https://bz.apache.org/bugzilla/show_bug.cgi?id=62318). The fix for that didn't account for an important edge case. When should we mark a worker health check as "updated", where "updated" means the last time it was checked? Originally, the worker was marked as "updated" when the check completed, though the timestamp used was when the check started. Any watchdog firings while the check was still running would trigger additional checks to run for that worker since the trigger condition was checking the "updated" timestamp that continued to have an old value until that check completed.

The previous fix used the same timestamp for "updated", but it changed when the timestamp was applied. It applied the timestamp at the beginning of the check. That (mostly) prevents additional checks from being triggered while the first one is running.

The edge case that isn't accounted for is when all of the threads in the pool used for health checks are busy. In that case, the "updated" timestamp is not applied until the health check task is popped from the queue and given to a thread to run. Let's look at an example (which I actually used experimentally). Suppose it takes 5 seconds to do a health check. That's a long time, but not preposterous. The watchdog callback runs every 100ms, and the default thread pool is 16 threads. With just a single worker to check, 49 additional checks will be triggered before the first check finishes. Each will carry a timestamp just 100ms later than the one just before it. The first 16 checks will be given to threads for immediate execution, with the final one updating "updated" 1.5 seconds later than the first one. The other 34 or so will be queued until threads free up to run them. Each of those queued health checks carries along with it a timestamp to be applied to "updated", and the timestamp reflects the time that the health check task was enqueued. There's just one "updated" field for the worker, regardless of how many health check tasks there are for that worker. The "updated" timestamp will always reflect the watchdog trigger time of the health check task that started most recently. In our example, the "updated" timestamps eventually be marked with a time about 5 seconds later than when the first check started.

With the default health check interval ("hcinterval") of 60 seconds, things settle down until the 65 second point or so. Then the cycle repeats. There is wasted effort of redundant health checks (which might foil expectations for "hcfails" and "hcpasses"), and the "hcinterval" is effectively changed from 60 seconds to about 65 seconds. Those things are undesirable but not a tragedy.

Having just a single worker is unlikely. For every worker of some kind getting health checks, the above scenario plays out. It's easy to get hundreds of health check tasks queued up waiting for threads to process them. Still, the net effect would be merely stretching the "hcinterval" time for each worker by the time it takes to do a check. It's 5 seconds in our example, but it would be way less for a healthy system. If the system is not healthy, the time it takes to do health check can be faster or slower. If we try to connect to a port with no listener process, then we will very quickly get a "connection refused". If an entire server is down, we won't get any response at all and will have to wait for a self-imposed socket timeout (from the "connectiontimeout" parameter, default 60s). Or, the process on the server might be in a weird state so that the health check takes a long time to complete without causing a socket timeout (from the "timeout" parameter, default 60s). If the time to complete the health check exceeds the "hcinterval" for the worker, we will never catch up. A growing number of health check tasks will be queued for that worker. Each queued health check task is holding a chunk of heap memory, and that is what accounts for the memory growth. (As one anecdotal data point, on Windows my httpd normally runs at 15-16 MB process size. With my pathological test case, it's easy for me to see it grow to a couple of GB over a couple hours or so with many tens of thousands of trapped health check tasks in the queue.)

So, what to do to workaround or fix this edge case?

* Workaround 1: Have at least as many threads in the thread pool (ProxyHCTPSize) as you have distinct workers getting health checks. That way, health check tasks will not usually get queued (though it still could happen occasionally, so maybe allocate some extra threads). The threads will be idle most of the time.

* Workaround 2: Make your health check intervals ("hcinterval") long enough to avoid the pathlogical case. That is, health checks will always complete, pass or fail, before the next check is due. Of course, you lose the benefit of more frequent health checks.

* Workaround 3: Don't use the thread pool for health checks, which you can do by setting ProxyHCTPSize=0. That will make all health checks synchronous, which is generally pretty undesirable.

* Fix 1: Apply the timestamp to "updated" before sending the health check task to the pool. In mod_proxy_hcheck.c, that's in the function hc_watchdog_callback() before the call to apr_thread_pool_push(). That will keep most additional health check tasks from being created for the same worker, though that can still happen if a health check takes longer than the health check interval.

* Fix 2: Put in an explcit check that a worker has a health check in flight, and don't create any new checks as long as that's true. This needs only a single bit flag in the worker data blob that already exists. Set that flag on the worker before you call apr_thread_pool_push() and clear the flag at the completion of hc_check(). I don't see the value in having simultaneious in-flight health checks for the same worker, but maybe someone else does.

If I were deciding, I would do both Fix 1 and Fix 2, though you could argue that Fix 2 makes Fix 1 unnecessary (depending on how you feel about the meaning of "hcinterval", as mentioned in the discussion of bug #62318). I have prototyped both fixes to verify that it resolves the problem (or certainly makes it much harder to trigger).

Thanks for the incredible bug report and the excellent investigation. I agree that Fixes 1+2 make the most sense. I'll look into adding them asap.

We are running into the same issue with our current configuration. Apache develops a serious memory leak hitting over 1.2 GB if one of the JVM's are started or stopped. We were on Apache 2.4.26 previously with the exact same configuration, and never ran into this. 
We are still waiting for a proper fix, any estimate on that?
Thank you,
Tudor

I can send out httpd configuration with what balancer HC's we run.

Created attachment 37621 [details]
Avoid concurrent checks

This patch resets the timestamp during the check (and prevents re-entering the check if the timestamp is zero), and then updates the timestamp after the check to schedule the next one.

That's fix 1 & 2 from comment 4.

How does it work for you?

Hello Yann,

I work with Tudor.
We already implemented that fix and it works as expected -> apache is stable and we are not encountering any memory leaks issues.
We have configured our hcinterval at 10 seconds (due to a LoadBalancer Ping Test), hcpasses=2 and increased the ProxyHCTPSize to 256 threads.
We wanted to know if/when this issue will be fixed coding-wise and not mitigated through configuration. 

Thank you,
Cristian Duca.

Hi Cristian,

(In reply to Cristian Duca from comment #8)
> 
> I work with Tudor.
> We already implemented that fix and it works as expected -> apache is stable
> and we are not encountering any memory leaks issues.

I'm not sure to understand, did you test the fix/patch from comment 7 already?

> We have configured our hcinterval at 10 seconds (due to a LoadBalancer Ping
> Test), hcpasses=2 and increased the ProxyHCTPSize to 256 threads.
> We wanted to know if/when this issue will be fixed coding-wise and not
> mitigated through configuration. 

If the fix you tested is this mitigation (by configuration), it would help / speed up the backport to 2.4 if you could test the patch (in the code) proposed in comment 7.
If it works with no particular mitigation in the configuration, then we can consider that it addresses the issue and do the backport to 2.4 (next release).

Hello, Yann,

I have tested the workaround by adding more ProxyHCTPSize.

Now I am trying to compile Apahce on Windows and to test the coding changes from comment 7 without any mitigations added into the Apache configuration -> at the moment I am not able to compile Apache on Windows -> Do you a wiki link on how to compile the latest apache-trunk source files by using VS2017?

Thank you,
Cristian Duca.

Hello, Yann,

I have compiled successfully apache on windows.
I have implemented the changes from Comment7 for the mod_proxy_hcheck module.

I can confirm that the fix from Comment7 works without any workarounds.

Can we expect to have this fix implemented in the next apache release build ?

Thank you,
Cristian Duca.

Fixed in 2.4.x (r1887119), will be in the upcoming release.