Dropped metrics from ddmd and mgd

[jmcarp]

Oximeter is currently dropping a subsample of metrics on the colo rack:

Investigating further, these failures all come from two producer ports, 8001 and 4677:

These metrics come from ddmd and mgd, and sure enough, there are gaps (note that these metrics should be sampled every 1s):

I think this means that collecting from these producers is often taking >1s. I think we should either figure out why and fix it, or figure out oximeter can better tolerate collection latencies greater than the sampling interval, or raise the sampling interval.

[lgfa29]

Messages we've found in colo that may be related:

20:55:30.843Z ERRO oximeter (oximeter-agent): timer-based collection request queue is full! This may indicate that the producer has a sampling interval that
 is too fast for the amount of data it generates
    collector_id = b78c24d9-be1c-428a-a844-d45819b90a74
    collector_ip = fd00:1122:3344:113::2b
    file = oximeter/collector/src/collection_task.rs:889
    interval = 1s
    producer_id = 0b196db0-d014-42c1-94c0-1c7ae3497dce
    producer_ip = fd00:1122:3344:11f::2
    producer_port = 8001

21:06:43.980Z WARN oximeter (oximeter-agent): failed to insert some results into metric DB
    collector_id = b78c24d9-be1c-428a-a844-d45819b90a74
    collector_ip = fd00:1122:3344:113::2b
    error = Failed to check out connection to database: No backends found for this service
    file = oximeter/collector/src/results_sink.rs:92

Querying the producer seems to be fast enough:

# while true; do time curl http://[fd00:1122:3344:10f::1]:8001/5fde67d2-ec74-4a2f-ac0e-60819e33ce5a > /dev/null; sleep 1; done
  % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current
                                 Dload  Upload  Total   Spent   Left   Speed
100  17332 100  17332   0      0  5.98M      0                              0

real    0m0.022s
user    0m0.007s
sys     0m0.014s
  % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current
                                 Dload  Upload  Total   Spent   Left   Speed
100  17332 100  17332   0      0  5.15M      0                              0

real    0m0.020s
user    0m0.006s
sys     0m0.013s
  % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current
                                 Dload  Upload  Total   Spent   Left   Speed
100  17332 100  17332   0      0  6.14M      0                              0

real    0m0.022s
user    0m0.007s
sys     0m0.014s
  % Total    % Received % Xferd  Average Speed  Time    Time    Time   Current
                                 Dload  Upload  Total   Spent   Left   Speed
100  17332 100  17332   0      0  5.42M      0                              0

real    0m0.022s
user    0m0.007s
sys     0m0.013s

[hermanol]

The question going forward is whether this is related to the connection pool that we build around ClickHouse, see Oximeter code here and here for the logs above.

[bnaecker]

The question going forward is whether this is related to the connection pool that we build around ClickHouse, see Oximeter code here and here for the logs above.

The first message is emitted when the collection interval elapses; we attempt to poll from the producer; but its last collection is still ongoing. That's exactly the situation when we increment the failed_collections counter with a reason "collections in progress". It's not related to the connection pooling errors.

The second error message is about the connection pool, and comes from this error in qorb. It means we tried to and failed to claim a connection, so the pool is all used. We'd have to dig into the behavior to understand why, e.g., if we're already using all the connections or something similar.

[jmcarp]

I took another look at this, and it may actually have already been fixed by @bnaecker in #10273. Given that a release is hopefully imminent, I think we should wait for r20 to land on the colo rack, then see if the issue resolves.