<p>Asp.Net Core microservices on Docker/Kubernetes are disagreeing on the duration of inter-service calls between the caller and callee.</p>

<p>The caller logs can show anywhere from a few milliseconds up to 10 full seconds more than the callee.  The problem worsens under heavy load, but is still present under light load.  Many calls do agree between the caller and callee, but this discrepancy does happen frequent enough to make a real dent in performance overall.</p>

<p>The timestamps indicate that the time gap can either be <em>before</em> or <em>after</em> the callee has reported that its response is complete.</p>

<p><strong>Example logs (numbers from a real time discrepancy)</strong>  </p>

<pre><code>ServiceB: [2018-10-11T22:41:41.374Z] S2S request complete to ServiceA, Duration: 11644
ServiceA: [2018-10-11T22:41:29.732Z] Request complete, Duration: 5
</code></pre>

<p><strong>Caller Timing (common class for all S2S calls)</strong>  </p>

<pre><code>var timer = Stopwatch.StartNew();
var response = await _httpClientFactory.CreateClient().SendAsync(request);
timer.Stop();
Logger.Info($"S2S request complete to {service}, Duration: {timer.EllapsedMilliseconds}");
</code></pre>

<p><strong>Callee Timing (custom Asp.Net middleware)</strong></p>

<pre><code>var timer = Stopwatch.StartNew();
await _next(context);
timer.Stop();
Logger.Info($"Request complete, Duration: {timer.EllapsedMilliseconds}");
</code></pre>

<p>This middleware is registered as almost the first in the pipeline (second to only the ActivityId / TraceId middleware for log correlation).</p>

<p><strong>Troubleshooting Steps</strong>  </p>

<ul>
<li>Not able to reproduce the issue on Windows development machine</li>
<li>Monitored CPU, Memory, Thread Count, GC Collects, Open Handles (all at reasonable levels)</li>
<li>Adjusted k8s spec CPU and Memory request / limit (various levels with some effect, but does not alleviate the problem)</li>
<li>Turned on Server GC with Environment Variable: COMPlus_gcServer=1</li>
<li>Issue occurs on services that are within resource limits and have not needed to autoscale</li>
<li>Changed to new Kestrel Socket Transport (instead of libuv)</li>
<li>Changed to new .Net Core 2.1 SocketsHttpHandler  </li>
</ul>

<p><strong>System Topology</strong></p>

<p>Asp.Net Core 2.1 self-hosted Kestrel<br>
.Net Core 2.1.5 runtime<br>
Docker / Kubernetes 1.10.5<br>
K8s Addons: kube-proxy, weave, etcd, SkyDNS<br>
AWS c5.4xlarge  </p>

<p><strong>Updates</strong>  </p>

<ol>
<li>Found out that the time gap can sometimes be before or after the callee starts/completes</li>
</ol>

TylerOhlsen
<p>In this case, this issue was fixed by <em>removing</em> the k8s spec CPU limit.  </p>

<p>Monitoring the <code>container_cpu_cfs_throttled_seconds_total</code> metric found that one of the service containers was getting <em>paused</em> very frequently.  These pauses were mostly on the caller side of the S2S calls.  Which increased the elapsed time reported by the caller.</p>

<p>Removing the CPU limit in the k8s spec prevents k8s from passing the <code>--cpu-quota</code> and <code>--cpu-period</code> <a href="https://docs.docker.com/config/containers/resource_constraints/#cpu" rel="nofollow noreferrer">docker parameters</a>.  Which is what controls the container pauses.</p>
