oohelperd: excessive CPU usage under moderate load

[bassosimone]

TL;DR We need to investigate high oohelperd CPU usage under load, which we noticed during an A/B testing session, but which seems to have been a lingering problem for the TH also before the A/B testing itself.

With my team members (and @FedericoCeratto and @sloncocs in particular), we have been investigating excessive CPU load in the oohelperd, which surfaced when A/B testing code we introduced in ooni/probe-cli#985.

We started testing this code on 2023-02-07T08:06:00Z by deploying a ~3.17.0-beta build on 0.th.ooni.org. On February 9, I said on our internal channels that I was a bit worried by the idle CPU after the deployment:

Further zooming out, though, I noticed there were previous moments in time where we had little CPU to spare, so I was not convinced that we could easily say the new code was the culprit (spoiler: it was not):

As you could see, in fact, in December we had lower available CPU that we had in early February. Because this fact was worrying me, I called for discussing this topic in the next backend meeting (February 14).

However, when I was back to the office after the weekend, I noticed that the CPU usage was now 100%:

While I was investigating, my colleague @sloncocs warned about a surge of failed tests over the weekend:

I quickly realized that, because the 0.th.ooni.org test helper was on its knees, it could not service many users. Therefore, several measurements that happened using such a test helper did not include the control measurement. Hence, the probe could not determine the status of the measurement (all good, website down, anomaly, etc).

Fifteen minutes after noticing this issue, I restarted the oohelperd. Since then, I have reverted back to running the previous code, thus interrupting the A/B testing session until it became more clear to us what was going on.

This issue is here to share what I have learned (so far) when investigating this issue.

[bassosimone]

The first problem to solve is how to stress test the oohelperd in a testing environment. To this end, @FedericoCeratto proposed using the siege tool to benchmark the oohelperd binary.

This is the script we have been using to perform this task:

#!/bin/bash
set -euxo pipefail
siege -c 10 -t30S \
  --content-type "application/json" \
  'http://127.0.0.1:8080 POST {"http_request": "https://www.youtube.com/", "http_request_headers": {}, "tcp_connect": ["216.58.209.46:443", "142.250.184.78:443", "142.250.184.110:443", "142.250.180.142:443", "142.250.180.174:443", "142.251.209.14:443", "142.251.209.46:443"]}'

The general idea here is to issue the same POST request with the given body for 30 seconds using ten concurrent users to create load on the system. I am personally testing this code in my development computer (which does not have lower hardware resources than the VM we are currently using for the test helpers).

[bassosimone]

With ooni/probe-cli#1096 applied, I ran the above script and got as output:

Lifting the server siege...
Transactions:		          45 hits
Availability:		      100.00 %
Elapsed time:		       30.08 secs
Data transferred:	        0.24 MB
Response time:		        4.79 secs
Transaction rate:	        1.50 trans/sec
Throughput:		        0.01 MB/sec
Concurrency:		        7.16
Successful transactions:          45
Failed transactions:	           0
Longest transaction:	       12.69
Shortest transaction:	        1.34

The pprof trace for oohelperd looked as follows:

If you download the SVG and zoom, you can see how netxlite.NewDefaultCertPool is eating lots of CPU.

So, I implemented ooni/probe-cli#1097 and ooni/probe-cli#1098 to create a static cached cert pool that we can use for both oohelperd and netxlite. The latter change is required because the oohelperd uses a netxlite HTTP client with default configuration, so it was always calling netxlite.NewDefaultCertPool when fetching webpages using HTTP.

With those two changes in place, the script output become:

Lifting the server siege...
Transactions:		         154 hits
Availability:		      100.00 %
Elapsed time:		       30.82 secs
Data transferred:	        0.82 MB
Response time:		        1.88 secs
Transaction rate:	        5.00 trans/sec
Throughput:		        0.03 MB/sec
Concurrency:		        9.41
Successful transactions:         154
Failed transactions:	           0
Longest transaction:	        4.07
Shortest transaction:	        1.24

While there's more to optimize, we have clearly removed a significant bottleneck.

[bassosimone]

I backported ooni/probe-cli#1097 to release/3.17 with ooni/probe-cli@ebb4ecc.

There was no need to backport ooni/probe-cli#1098. After resolving conflicts, the remaining diff boiled down to:

diff --git a/internal/netxlite/quic.go b/internal/netxlite/quic.go
index 682c976e..c4641c88 100644
--- a/internal/netxlite/quic.go
+++ b/internal/netxlite/quic.go
@@ -166,7 +166,8 @@ func (d *quicDialerQUICGo) dialEarlyContext(ctx context.Context,
 func (d *quicDialerQUICGo) maybeApplyTLSDefaults(config *tls.Config, port int) *tls.Config {
        config = config.Clone()
        if config.RootCAs == nil {
-               config.RootCAs = defaultCertPool
+               // See https://github.com/ooni/probe/issues/2413 for context
+               config.RootCAs = tproxyDefaultCertPool
        }
        if len(config.NextProtos) <= 0 {
                switch port {
diff --git a/internal/netxlite/tls.go b/internal/netxlite/tls.go
index dc87743a..8f7e781b 100644
--- a/internal/netxlite/tls.go
+++ b/internal/netxlite/tls.go
@@ -213,7 +213,8 @@ func (h *tlsHandshakerConfigurable) Handshake(
        conn.SetDeadline(time.Now().Add(timeout))
        if config.RootCAs == nil {
                config = config.Clone()
-               config.RootCAs = defaultCertPool
+               // See https://github.com/ooni/probe/issues/2413 for context
+               config.RootCAs = tproxyDefaultCertPool
        }
        tlsconn, err := h.newConn(conn, config)
        if err != nil {
diff --git a/internal/netxlite/tproxy.go b/internal/netxlite/tproxy.go
index c56b853e..0043ed12 100644
--- a/internal/netxlite/tproxy.go
+++ b/internal/netxlite/tproxy.go
@@ -15,6 +15,16 @@ var TProxy model.UnderlyingNetwork = &DefaultTProxy{}
 // defaultTProxy is the default UnderlyingNetwork implementation.
 type DefaultTProxy struct{}
 
+// tproxyDefaultCertPool is a static copy of the default cert pool. You
+// MUST NOT access this variable directly. You SHOULD use the
+// tproxySingleton().DefaultCertPool() factory instead. By doing
+// that, you would allow integration tests to override the pool
+// we're using. Hence, we can run tests with fake servers.
+//
+// See https://github.com/ooni/probe/issues/2413 to understand why we
+// need a private static default pool.
+var tproxyDefaultCertPool = NewDefaultCertPool()
+
 // DialContext implements UnderlyingNetwork.
 func (tp *DefaultTProxy) DialContext(ctx context.Context, timeout time.Duration, network, address string) (net.Conn, error) {
        d := &net.Dialer{

From this diff it's clear that release/3.17 already used a private cert pool. This means that ooni/probe-cli#1068 and ooni/probe-cli#1069 were introducing a performance regression in that they always called NewDefaultCertPool when using a private static pool would have been better.

Hence, with ooni/probe-cli@ebb4ecc merged into release/3.17, we are now in a good place to evaluate whether we improved the situation for release/3.17.

[bassosimone]

In the meanwhile, we have updated our test helpers architecture in ooni/api@3bf3bef. The general idea is to use 0.th as the place where we do A/B testing after code has been tested on the testing infrastructure. This test helper will receive a small portion of the traffic. The other THs will always run stable code and will round robin the rest of the traffic.

[bassosimone]

To make the developed diff benefit all experiments, we should make sure we are not calling NewDefaultCertPool every time an experiment runs. We did this in ooni/probe-cli#1102.

[bassosimone]

We should also expose pprof metrics to localhost and think about which additional prometheus metrics we should expose in dashboards. We have already added the number of currently allocated bytes and the GC duration.

[bassosimone]

In ooni/probe-cli#1104, I have added support for obtaining the profile of a running instance. In ooni/probe-cli#1105, I made oohelperd deployment easier. We should now write a short runbook explaining how to extract performance metrics from a running oohelperd daemon.

[bassosimone]

We have put work in to mitigate the CPU usage and we now have support for collecting metrics. Additionally, we are now using four test helpers and we disabled using HTTP/3 in the TH for now. I will close the issue right now, because otherwise this will become a long-running issue with no ending condition in sight. Should we see new performance issues in the future, we will reopen this issue or create a new issue.