{"id":494430,"date":"2026-09-11T19:05:15","date_gmt":"2026-09-11T19:05:15","guid":{"rendered":"https:\/\/savepearlharbor.com\/?p=494430"},"modified":"-0001-11-30T00:00:00","modified_gmt":"-0001-11-29T21:00:00","slug":"","status":"publish","type":"post","link":"https:\/\/savepearlharbor.com\/?p=494430","title":{"rendered":"I Kept the Same 300\u00a0Test Durations and Changed Only Their Order. p95\u00a0and p99\u00a0Missed the Slow Streaks"},"content":{"rendered":"<div xmlns=\"http:\/\/www.w3.org\/1999\/xhtml\">\n<p>After my previous experiments with test latency, I started wondering whether I was still looking at the wrong statistic.<\/p>\n<p>Mean latency is obviously incomplete.<\/p>\n<p>p95\u00a0is better.<\/p>\n<p>p99\u00a0is useful when rare slow runs matter.<\/p>\n<p>But all of these measurements have one property that is easy to overlook:<\/p>\n<p>They do not care about order.<\/p>\n<p>If I take 300\u00a0test durations and randomly rearrange them, the mean remains identical.<\/p>\n<p>So do p50, p95\u00a0and p99.<\/p>\n<p>The total waiting time is identical too.<\/p>\n<p>Yet from a developer perspective, ten slow runs scattered across an afternoon do not necessarily feel like ten slow runs arriving almost back to back.<\/p>\n<p>That gave me a very specific experiment.<\/p>\n<p>I generated one set of 300\u00a0test durations.<\/p>\n<p>Then I created two timelines from exactly the same values.<\/p>\n<p>In the first timeline, durations were randomly ordered.<\/p>\n<p>In the second, slow runs were deliberately clustered.<\/p>\n<p>Nothing else changed.<\/p>\n<p>The result surprised me more than changing the latency distribution itself.<\/p>\n<p>Both timelines had:<\/p>\n<pre><code>mean:  7.65 sp50:   5.49 sp95:  17.20 sp99:  42.66 smax:  49.24 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:87px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>Both contained exactly the same total waiting time:<\/p>\n<pre><code>2295.83 seconds<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>That is about 38.26\u00a0minutes.<\/p>\n<p>A latency dashboard based only on percentiles would describe the two workloads as identical.<\/p>\n<p>But one timeline contained an 18-run streak of tests slower than 12\u00a0seconds.<\/p>\n<p>The other never exceeded two.<\/p>\n<p>That is the part I wanted to understand.<\/p>\n<figure class=\"full-width \"><img decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/7d4\/4fa\/a81\/7d44faa8111ae6e8d009237e5bbc041a.png\" width=\"1672\" height=\"941\" sizes=\"auto, (max-width: 780px) 100vw, 50vw\" srcset=\"https:\/\/habrastorage.org\/r\/w780\/getpro\/habr\/upload_files\/7d4\/4fa\/a81\/7d44faa8111ae6e8d009237e5bbc041a.png 780w,&#10;       https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/7d4\/4fa\/a81\/7d44faa8111ae6e8d009237e5bbc041a.png 781w\" loading=\"lazy\" decode=\"async\"\/><\/figure>\n<h3>First I needed the same data, not merely similar data<\/h3>\n<p>I did not want to compare two independently generated distributions.<\/p>\n<p>If I generated one fast workload and one bursty workload separately, a difference in the result could always be explained by slightly different samples.<\/p>\n<p>So I created the durations once.<\/p>\n<p>The synthetic workload contains mostly short test runs, a smaller group of medium ones, and a few expensive runs.<\/p>\n<p>The generator looked roughly like this:<\/p>\n<pre><code>import numpy as nprng = np.random.default_rng(42)n = 300u = rng.random(n)durations = np.empty(n)for i, x in enumerate(u):    if x &lt; 0.78:        durations[i] = np.clip(            rng.lognormal(np.log(5), 0.25),            2.5,            9        )    elif x &lt; 0.95:        durations[i] = np.clip(            rng.lognormal(np.log(12), 0.25),            8,            22        )    else:        durations[i] = np.clip(            rng.lognormal(np.log(38), 0.22),            25,            60        )<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>This is not production telemetry.<\/p>\n<p>It is a synthetic workload designed to give me a realistic\u2011looking mixture of ordinary test runs and occasional expensive ones.<\/p>\n<p>The important part is what happens afterward.<\/p>\n<p>I never regenerate those 300\u00a0numbers.<\/p>\n<p>Every comparison uses the exact same multiset of durations.<\/p>\n<p>That means every ordinary distribution statistic is guaranteed to remain unchanged when I rearrange them.<\/p>\n<h3>The random timeline<\/h3>\n<p>For the first sequence I simply shuffled the 300\u00a0durations.<\/p>\n<pre><code>rng = np.random.default_rng(123)random_order = durations[    rng.permutation(len(durations))]<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>This produced the kind of timeline I normally imagine when looking at a histogram.<\/p>\n<p>Fast run.<\/p>\n<p>Fast run.<\/p>\n<p>Slow one.<\/p>\n<p>A few fast runs.<\/p>\n<p>Medium run.<\/p>\n<p>Another fast run.<\/p>\n<p>Occasional large spike.<\/p>\n<p>Nothing particularly interesting happens temporally.<\/p>\n<p>There are 37\u00a0runs above 12\u00a0seconds in the dataset.<\/p>\n<p>In this ordering, the longest consecutive streak above 12\u00a0seconds was only two runs.<\/p>\n<p>A developer might see something like:<\/p>\n<pre><code>5s4s13s16s6s5s7s4s41s6s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>There are unpleasant waits, but they are separated by ordinary feedback cycles.<\/p>\n<p>Then I rearranged exactly the same numbers.<\/p>\n<h3>Creating a clustered timeline without changing the distribution<\/h3>\n<p>I needed a way to introduce temporal persistence.<\/p>\n<p>Simply sorting the durations from fastest to slowest would be too artificial.<\/p>\n<p>Real degradation usually does not look like that.<\/p>\n<p>A CI worker gets overloaded for some period.<\/p>\n<p>A dependency becomes slow.<\/p>\n<p>Disk contention appears.<\/p>\n<p>A shared runner gets noisy.<\/p>\n<p>A cache becomes cold.<\/p>\n<p>Then the system recovers.<\/p>\n<p>So I generated a latent time series with positive autocorrelation.<\/p>\n<p>The model was:<\/p>\n<pre><code>z[t] = 0.9 \u00d7 z[t-1] + \u03b5[t]<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>where \u03b5 is random Gaussian noise.<\/p>\n<p>The coefficient 0.9\u00a0creates persistence.<\/p>\n<p>When the latent state becomes high, it tends to remain high for a while.<\/p>\n<p>When it becomes low, it tends to remain low.<\/p>\n<p>Then I ranked the 300\u00a0timeline positions by this latent value and assigned the slowest test durations to the highest positions.<\/p>\n<p>In simplified Python:<\/p>\n<pre><code>rng = np.random.default_rng(7)z = np.zeros(300)eps = rng.normal(size=300)for t in range(1, 300):    z[t] = 0.9 * z[t - 1] + eps[t]positions = np.argsort(z)sorted_durations = np.sort(durations)clustered = np.empty(300)clustered[positions] = sorted_durations<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>This operation does something useful.<\/p>\n<p>It changes temporal structure without changing a single duration.<\/p>\n<p>The 49.24-second test is still there.<\/p>\n<p>The 17-second tests are still there.<\/p>\n<p>Every 5-second test is still there.<\/p>\n<p>Nothing has been added or removed.<\/p>\n<p>Only their positions changed.<\/p>\n<h3>And every normal percentile remained identical<\/h3>\n<p>This part is mathematically trivial, but I think it is the most important part of the experiment.<\/p>\n<p>Quantiles depend on the sorted values.<\/p>\n<p>A permutation does not change the sorted values.<\/p>\n<p>Therefore:<\/p>\n<pre><code>mean(random) = mean(clustered)p50(random) = p50(clustered)p95(random) = p95(clustered)p99(random) = p99(clustered)sum(random) = sum(clustered)<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>For both sequences I got:<\/p>\n<pre><code>mean  = 7.65 sp50   = 5.49 sp95   = 17.20 sp99   = 42.66 smax   = 49.24 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>If these were two CI pipelines and my monitoring showed only these numbers, I would conclude that their test latency was effectively identical.<\/p>\n<p>That conclusion would be technically correct.<\/p>\n<p>It would also miss something fairly large.<\/p>\n<h3>The first number that exposed the difference was autocorrelation<\/h3>\n<p>I calculated lag-1\u00a0autocorrelation.<\/p>\n<p>In this case I am asking a simple question:<\/p>\n<p>Does knowing the duration of the current test run tell me anything about the duration of the next one?<\/p>\n<p>For the randomly ordered sequence, lag-1\u00a0autocorrelation was about:<\/p>\n<pre><code>0.10<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>For the clustered sequence:<\/p>\n<pre><code>0.83<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>That is a completely different system.<\/p>\n<p>With low serial correlation, a slow run tells me little about what happens next.<\/p>\n<p>With strong positive serial correlation, a slow run makes another slow run much more likely.<\/p>\n<p>This is something p99\u00a0cannot express.<\/p>\n<p>p99\u00a0tells me how large the upper tail is.<\/p>\n<p>It does not tell me whether those tail events are isolated or arrive together.<\/p>\n<h3>Then I counted slow streaks<\/h3>\n<p>I picked 12\u00a0seconds as an analytical threshold.<\/p>\n<p>This is not meant to be a universal threshold for human attention.<\/p>\n<p>I just needed a fixed line above which a test run would be classified as slow for this experiment.<\/p>\n<p>There were 37\u00a0such runs in both sequences.<\/p>\n<p>Again, exactly the same number.<\/p>\n<p>In the random sequence, the longest consecutive streak above 12\u00a0seconds was:<\/p>\n<pre><code>2<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>In the clustered sequence:<\/p>\n<pre><code>18<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>That difference is hard to see in a percentile.<\/p>\n<p>The two datasets have the same number of slow tests.<\/p>\n<p>But one can produce something like this:<\/p>\n<pre><code>slowslowfastfastfastslowfastfast<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>while the other can produce:<\/p>\n<pre><code>slowslowslowslowslowslowslowslow...<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>By the eighteenth slow feedback cycle, I am no longer looking at a rare latency spike.<\/p>\n<p>I am experiencing a slow period.<\/p>\n<p>That distinction seems important.<\/p>\n<h3>Five\u2011cycle windows made the difference even clearer<\/h3>\n<p>Individual latency is not always the most useful unit.<\/p>\n<p>When I am coding, I usually care about a sequence of feedback loops.<\/p>\n<p>Write something.<\/p>\n<p>Run tests.<\/p>\n<p>Fix something.<\/p>\n<p>Run them again.<\/p>\n<p>Change another line.<\/p>\n<p>Run them again.<\/p>\n<p>So I calculated the average latency inside every consecutive five\u2011run window.<\/p>\n<p>For each timeline I then found the worst five\u2011run period.<\/p>\n<p>In the random sequence, the worst five\u2011run average was approximately:<\/p>\n<pre><code>22.23 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>In the clustered sequence:<\/p>\n<pre><code>42.10 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>Remember that the global mean in both cases is still:<\/p>\n<pre><code>7.65 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>Nothing about the distribution changed.<\/p>\n<p>Yet at the local level, the clustered timeline produced a five\u2011cycle period where the average feedback delay was almost twice as high.<\/p>\n<p>I repeated the calculation with ten\u2011run windows.<\/p>\n<p>The worst ten\u2011run average in the random ordering was approximately:<\/p>\n<pre><code>14.40 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>For the clustered ordering:<\/p>\n<pre><code>35.88 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>This is where the global average becomes almost misleading.<\/p>\n<p>A pipeline can have a perfectly acceptable daily mean while still producing terrible local periods.<\/p>\n<h3>I did not want the result to depend on one lucky shuffle<\/h3>\n<p>At this point I had one random sequence and one clustered sequence.<\/p>\n<p>That is not enough.<\/p>\n<p>The random sequence might simply have been unusually well behaved.<\/p>\n<p>So I took the same 300\u00a0durations and performed 10,000\u00a0independent random permutations.<\/p>\n<p>For each permutation I calculated the longest streak above 12\u00a0seconds.<\/p>\n<p>The median longest streak was:<\/p>\n<pre><code>2<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>The 95th percentile was:<\/p>\n<pre><code>4<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>The largest streak I saw across all 10,000\u00a0random permutations was:<\/p>\n<pre><code>6<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>The clustered sequence produced:<\/p>\n<pre><code>18<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>I also repeated the analysis for the worst five\u2011run average.<\/p>\n<p>Across 10,000\u00a0random orderings, the median maximum five\u2011run average was about:<\/p>\n<pre><code>19.63 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>The 95th percentile was:<\/p>\n<pre><code>24.55 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>The 99th percentile was:<\/p>\n<pre><code>27.77 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>The clustered sequence reached:<\/p>\n<pre><code>42.10 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>The same thing happened with ten\u2011run windows.<\/p>\n<p>For random permutations, the median worst ten\u2011run average was about 14.56\u00a0seconds.<\/p>\n<p>The 95th percentile was 17.85\u00a0seconds.<\/p>\n<p>The 99th percentile was 19.64\u00a0seconds.<\/p>\n<p>The clustered timeline reached 35.88\u00a0seconds.<\/p>\n<p>At that point I stopped thinking of this as a weird permutation.<\/p>\n<p>The temporal structure was producing a property the ordinary latency distribution simply did not contain.<\/p>\n<h3>Percentiles deliberately throw away order<\/h3>\n<p>This is not a criticism of percentiles.<\/p>\n<p>p95\u00a0is doing exactly what it is supposed to do.<\/p>\n<p>Take 300\u00a0measurements.<\/p>\n<p>Sort them.<\/p>\n<p>Look near the upper end.<\/p>\n<p>Once I sort the observations, time disappears.<\/p>\n<p>The test that happened at 10:01\u00a0and the test that happened at 16:47\u00a0are now just two numbers in an ordered array.<\/p>\n<p>That is useful when I want to know how slow the slowest portion of requests tends to be.<\/p>\n<p>It is useless when the question is whether slow events arrive in clusters.<\/p>\n<p>Mathematically, any metric that is invariant under permutation cannot detect temporal clustering.<\/p>\n<p>Mean is permutation\u2011invariant.<\/p>\n<p>Variance is permutation\u2011invariant.<\/p>\n<p>Median is permutation\u2011invariant.<\/p>\n<p>p95\u00a0is permutation\u2011invariant.<\/p>\n<p>p99\u00a0is permutation\u2011invariant.<\/p>\n<p>A histogram is permutation\u2011invariant.<\/p>\n<p>I can completely rearrange the experience while leaving every one of those measurements untouched.<\/p>\n<p>That was the part I had underestimated.<\/p>\n<h3>Variance was not enough either<\/h3>\n<p>This was particularly interesting after my previous experiment.<\/p>\n<p>I had already been looking at latency variance and how unpredictable test times can change the feedback loop.<\/p>\n<p>But variance has the same problem here.<\/p>\n<p>Because the underlying 300\u00a0durations are identical, the variance is identical too.<\/p>\n<p>I can preserve:<\/p>\n<pre><code>meanvariancep50p95p99minimummaximumtotal waiting time<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>and still create radically different slow streaks.<\/p>\n<p>So there are really two separate dimensions.<\/p>\n<p>The first is marginal variability.<\/p>\n<p>How different are individual test durations from each other?<\/p>\n<p>The second is temporal dependence.<\/p>\n<p>Does a slow test tend to be followed by another slow test?<\/p>\n<p>A normal latency histogram can describe the first.<\/p>\n<p>It says almost nothing about the second.<\/p>\n<h3>A simple example outside testing made this obvious to me<\/h3>\n<p>Imagine two services.<\/p>\n<p>Both have a 1\u00a0percent error rate.<\/p>\n<p>Service A returns one failed request roughly every hundred requests.<\/p>\n<p>Service B works perfectly for hours and then fails one hundred requests in a row.<\/p>\n<p>Same total request count.<\/p>\n<p>Same number of errors.<\/p>\n<p>Same 1\u00a0percent error rate.<\/p>\n<p>Very different operational behaviour.<\/p>\n<p>Latency can have the same problem.<\/p>\n<p>Ten 40-second test runs spread across a day are one thing.<\/p>\n<p>Ten 40-second runs arriving in one development session are something else.<\/p>\n<p>Aggregation can make both look identical.<\/p>\n<h3>Where could these clusters come from in a real CI system?<\/h3>\n<p>I can think of several mechanisms that could create serial dependence without dramatically changing the long\u2011term histogram.<\/p>\n<p>A shared runner can become temporarily saturated.<\/p>\n<p>Several jobs can compete for disk bandwidth at the same time.<\/p>\n<p>A remote dependency can enter a slow period.<\/p>\n<p>A container image or dependency cache can repeatedly miss after an invalidation.<\/p>\n<p>CPU throttling can persist for several runs.<\/p>\n<p>A noisy neighbour can affect the same worker for minutes rather than milliseconds.<\/p>\n<p>Garbage collection or memory pressure can become correlated with workload phases.<\/p>\n<p>Test ordering can move expensive integration tests into the same region of the suite.<\/p>\n<p>The exact mechanism is not important for this experiment.<\/p>\n<p>What matters is that many real performance problems have state.<\/p>\n<p>They do not independently reroll themselves from scratch for every execution.<\/p>\n<p>Once a machine becomes overloaded, the next execution is more likely to run on an overloaded machine too.<\/p>\n<p>That produces memory in the latency process.<\/p>\n<h3>This changes what I would put on a test\u2011latency dashboard<\/h3>\n<p>I would still keep mean, p50, p95\u00a0and p99.<\/p>\n<p>They answer useful questions.<\/p>\n<p>But for a feedback loop used hundreds of times per day, I would also want some measure of temporal structure.<\/p>\n<p>Lag autocorrelation is one option.<\/p>\n<p>Rolling latency is another.<\/p>\n<p>Maximum rolling averages can expose bad local periods.<\/p>\n<p>Run\u2011length statistics can show how often slow executions arrive consecutively.<\/p>\n<p>Even a simple chart of latency against execution order can reveal things that a histogram hides immediately.<\/p>\n<p>I do not think every engineering dashboard needs a full time\u2011series analysis section.<\/p>\n<p>But if developers complain that tests are sometimes unusably slow while the daily p95\u00a0looks fine, I would no longer assume that one of them is wrong.<\/p>\n<p>They may simply be measuring different properties.<\/p>\n<h3>There is a trap in daily aggregation<\/h3>\n<p>Suppose I run tests 300\u00a0times during a working period.<\/p>\n<p>For 250\u00a0runs everything feels normal.<\/p>\n<p>Then the CI environment enters a bad state.<\/p>\n<p>The next 20\u00a0runs become slow.<\/p>\n<p>Later it recovers.<\/p>\n<p>At the end of the day I calculate one p95\u00a0value.<\/p>\n<p>I have compressed the entire sequence into a single number.<\/p>\n<p>The temporary degradation becomes part of the tail, but the fact that it happened as one contiguous event disappears.<\/p>\n<p>This matters operationally too.<\/p>\n<p>If I only investigate the slowest individual runs, I may look for a problem inside particular tests.<\/p>\n<p>But if slow runs are highly autocorrelated, the cause may live outside the tests completely.<\/p>\n<p>The runner matters.<\/p>\n<p>The machine matters.<\/p>\n<p>The network matters.<\/p>\n<p>The current load matters.<\/p>\n<p>The previous run may suddenly become relevant evidence.<\/p>\n<h3>I would now ask one more question when looking at latency<\/h3>\n<p>Previously, if somebody showed me:<\/p>\n<pre><code>mean 7.6 sp95 17.2 sp99 42.7 s<\/code><div class=\"code-explainer\"><a href=\"https:\/\/sourcecraft.dev\/\" class=\"tm-button code-explainer__link\" style=\"visibility: hidden;\"><img style=\"width:14px;height:14px;object-fit:cover;object-position:left;\"\/><\/a><\/div><\/pre>\n<p>I would immediately start reasoning about the distribution.<\/p>\n<p>How heavy is the tail?<\/p>\n<p>Are rare integration tests responsible?<\/p>\n<p>Would reducing p99\u00a0improve the feedback loop?<\/p>\n<p>Now I would ask something else first:<\/p>\n<p>Where are those slow runs in time?<\/p>\n<p>If they are independent spikes, one optimization strategy may make sense.<\/p>\n<p>If they arrive in persistent clusters, I may be looking at a completely different failure mode.<\/p>\n<p>The distinction cannot be recovered from the percentiles afterward.<\/p>\n<p>Once I throw away the ordering, the information is gone.<\/p>\n<h3>What this experiment does not prove<\/h3>\n<p>There is one limitation I want to make explicit.<\/p>\n<p>I did not measure developers.<\/p>\n<p>I did not put two groups of programmers in front of these timelines and measure concentration, task completion, eye movement or context switching.<\/p>\n<p>So this experiment does not prove that an 18-run slow streak reduces human productivity by some particular percentage.<\/p>\n<p>That would require a different study.<\/p>\n<p>What I demonstrated is narrower.<\/p>\n<p>Two test\u2011latency sequences can have exactly the same durations, the same mean, the same variance, the same percentiles and the same total waiting time while having radically different temporal behaviour.<\/p>\n<p>Whether that temporal behaviour harms a particular developer is a separate question.<\/p>\n<p>But if I want to study developer feedback loops, ignoring it now seems like a fairly large omission.<\/p>\n<h3>The surprising part was how little I had to change<\/h3>\n<p>I originally expected to discover something only after changing the latency distribution.<\/p>\n<p>Increase variance.<\/p>\n<p>Add a heavier tail.<\/p>\n<p>Raise p99.<\/p>\n<p>Make a few tests much slower.<\/p>\n<p>None of that was necessary.<\/p>\n<p>I kept every latency value.<\/p>\n<p>I kept every percentile.<\/p>\n<p>I kept all 2295.83\u00a0seconds of waiting.<\/p>\n<p>Then I moved the numbers around.<\/p>\n<p>That alone changed the longest slow streak from two runs to eighteen and pushed the worst five\u2011cycle average from roughly 22\u00a0seconds to 42\u00a0seconds.<\/p>\n<p>The global statistics did not move at all.<\/p>\n<p>The timeline did.<\/p>\n<p>And for a developer sitting in front of the test runner, the timeline is the thing that actually happens.<\/p>\n<\/div>\n<p>\u0441\u0441\u044b\u043b\u043a\u0430 \u043d\u0430 \u043e\u0440\u0438\u0433\u0438\u043d\u0430\u043b \u0441\u0442\u0430\u0442\u044c\u0438 <a href=\"https:\/\/habr.com\/ru\/articles\/1081454\/\">https:\/\/habr.com\/ru\/articles\/1081454\/<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"<p>After my previous experiments with test latency, I started wondering whether I was still looking at the wrong statistic.Mean latency is obviously incomplete.p95\u00a0is better.p99\u00a0is useful when rare slow runs matter.But all of these measurements have one property that is easy to overlook:They do not care about order.If I take 300\u00a0test durations and randomly rearrange them, the mean remains identical.So do p50, p95\u00a0and p99.The total waiting time is identical too.Yet from a developer perspective, ten slow runs scattered across an afternoon do not necessarily feel like ten slow runs arriving almost back to back.That gave me a very specific experiment.I generated one set of 300\u00a0test durations.Then I created two timelines from exactly the same values.In the first timeline, durations were randomly ordered.In the second, slow runs were deliberately clustered.Nothing else changed.The result surprised me more than changing the latency distribution itself.Both timelines had:mean:  7.65 sp50:   5.49 sp95:  17.20 sp99:  42.66 smax:  49.24 sBoth contained exactly the same total waiting time:2295.83 secondsThat is about 38.26\u00a0minutes.A latency dashboard based only on percentiles would describe the two workloads as identical.But one timeline contained an 18-run streak of tests slower than 12\u00a0seconds.The other never exceeded two.That is the part I wanted to understand.First I needed the same data, not merely similar dataI did not want to compare two independently generated distributions.If I generated one fast workload and one bursty workload separately, a difference in the result could always be explained by slightly different samples.So I created the durations once.The synthetic workload contains mostly short test runs, a smaller group of medium ones, and a few expensive runs.The generator looked roughly like this:import numpy as nprng = np.random.default_rng(42)n = 300u = rng.random(n)durations = np.empty(n)for i, x in enumerate(u):    if x &lt; 0.78:        durations[i] = np.clip(            rng.lognormal(np.log(5), 0.25),            2.5,            9        )    elif x &lt; 0.95:        durations[i] = np.clip(            rng.lognormal(np.log(12), 0.25),            8,            22        )    else:        durations[i] = np.clip(            rng.lognormal(np.log(38), 0.22),            25,            60        )This is not production telemetry.It is a synthetic workload designed to give me a realistic\u2011looking mixture of ordinary test runs and occasional expensive ones.The important part is what happens afterward.I never regenerate those 300\u00a0numbers.Every comparison uses the exact same multiset of durations.That means every ordinary distribution statistic is guaranteed to remain unchanged when I rearrange them.The random timelineFor the first sequence I simply shuffled the 300\u00a0durations.rng = np.random.default_rng(123)random_order = durations[    rng.permutation(len(durations))]This produced the kind of timeline I normally imagine when looking at a histogram.Fast run.Fast run.Slow one.A few fast runs.Medium run.Another fast run.Occasional large spike.Nothing particularly interesting happens temporally.There are 37\u00a0runs above 12\u00a0seconds in the dataset.In this ordering, the longest consecutive streak above 12\u00a0seconds was only two runs.A developer might see something like:5s4s13s16s6s5s7s4s41s6sThere are unpleasant waits, but they are separated by ordinary feedback cycles.Then I rearranged exactly the same numbers.Creating a clustered timeline without changing the distributionI needed a way to introduce temporal persistence.Simply sorting the durations from fastest to slowest would be too artificial.Real degradation usually does not look like that.A CI worker gets overloaded for some period.A dependency becomes slow.Disk contention appears.A shared runner gets noisy.A cache becomes cold.Then the system recovers.So I generated a latent time series with positive autocorrelation.The model was:z[t] = 0.9 \u00d7 z[t-1] + \u03b5[t]where \u03b5 is random Gaussian noise.The coefficient 0.9\u00a0creates persistence.When the latent state becomes high, it tends to remain high for a while.When it becomes low, it tends to remain low.Then I ranked the 300\u00a0timeline positions by this latent value and assigned the slowest test durations to the highest positions.In simplified Python:rng = np.random.default_rng(7)z = np.zeros(300)eps = rng.normal(size=300)for t in range(1, 300):    z[t] = 0.9 * z[t &#8212; 1] + eps[t]positions = np.argsort(z)sorted_durations = np.sort(durations)clustered = np.empty(300)clustered[positions] = sorted_durationsThis operation does something useful.It changes temporal structure without changing a single duration.The 49.24-second test is still there.The 17-second tests are still there.Every 5-second test is still there.Nothing has been added or removed.Only their positions changed.And every normal percentile remained identicalThis part is mathematically trivial, but I think it is the most important part of the experiment.Quantiles depend on the sorted values.A permutation does not change the sorted values.Therefore:mean(random) = mean(clustered)p50(random) = p50(clustered)p95(random) = p95(clustered)p99(random) = p99(clustered)sum(random) = sum(clustered)For both sequences I got:mean  = 7.65 sp50   = 5.49 sp95   = 17.20 sp99   = 42.66 smax   = 49.24 sIf these were two CI pipelines and my monitoring showed only these numbers, I would conclude that their test latency was effectively identical.That conclusion would be technically correct.It would also miss something fairly large.The first number that exposed the difference was autocorrelationI calculated lag-1\u00a0autocorrelation.In this case I am asking a simple question:Does knowing the duration of the current test run tell me anything about the duration of the next one?For the randomly ordered sequence, lag-1\u00a0autocorrelation was about:0.10For the clustered sequence:0.83That is a completely different system.With low serial correlation, a slow run tells me little about what happens next.With strong positive serial correlation, a slow run makes another slow run much more likely.This is something p99\u00a0cannot express.p99\u00a0tells me how large the upper tail is.It does not tell me whether those tail events are isolated or arrive together.Then I counted slow streaksI picked 12\u00a0seconds as an analytical threshold.This is not meant to be a universal threshold for human attention.I just needed a fixed line above which a test run would be classified as slow for this experiment.There were 37\u00a0such runs in both sequences.Again, exactly the same number.In the random sequence, the longest consecutive streak above 12\u00a0seconds was:2In the clustered sequence:18That difference is hard to see in a percentile.The two datasets have the same number of slow tests.But one can produce something like this:slowslowfastfastfastslowfastfastwhile the other can produce:slowslowslowslowslowslowslowslow&#8230;By the eighteenth slow feedback cycle, I am no longer looking at a rare latency spike.I am experiencing a slow period.That distinction seems important.Five\u2011cycle windows made the difference even clearerIndividual latency is not always the most useful unit.When I am coding, I usually care about a sequence of feedback loops.Write something.Run tests.Fix something.Run them again.Change another line.Run them again.So I calculated the average latency inside every consecutive five\u2011run window.For each timeline I then found the worst five\u2011run period.In the random sequence, the worst five\u2011run average was approximately:22.23 sIn the clustered sequence:42.10 sRemember that the global mean in both cases is still:7.65 sNothing about the distribution changed.Yet at the local level, the clustered timeline produced a five\u2011cycle period where the average feedback delay was almost twice as high.I repeated the calculation with ten\u2011run windows.The worst ten\u2011run average in the random ordering was approximately:14.40 sFor the clustered ordering:35.88 sThis is where the global average becomes almost misleading.A pipeline can have a perfectly acceptable daily mean while still producing terrible local periods.I did not want the result to depend on one lucky shuffleAt this point I had one random sequence and one clustered sequence.That is not enough.The random sequence might simply have been unusually well behaved.So I took the same 300\u00a0durations and performed 10,000\u00a0independent random permutations.For each permutation I calculated the longest streak above 12\u00a0seconds.The median longest streak was:2The 95th percentile was:4The largest streak I saw across all 10,000\u00a0random permutations was:6The clustered sequence produced:18I also repeated the analysis for the worst five\u2011run average.Across 10,000\u00a0random orderings, the median maximum five\u2011run average was about:19.63 sThe 95th percentile was:24.55 sThe 99th percentile was:27.77 sThe clustered sequence reached:42.10 sThe same thing happened with ten\u2011run windows.For random permutations, the median worst ten\u2011run average was about 14.56\u00a0seconds.The 95th percentile was 17.85\u00a0seconds.The 99th percentile was 19.64\u00a0seconds.The clustered timeline reached 35.88\u00a0seconds.At that point I stopped thinking of this as a weird permutation.The temporal structure was producing a property the ordinary latency distribution simply did not contain.Percentiles deliberately throw away orderThis is not a criticism of percentiles.p95\u00a0is doing exactly what it is supposed to do.Take 300\u00a0measurements.Sort them.Look near the upper end.Once I sort the observations, time disappears.The test that happened at 10:01\u00a0and the test that happened at 16:47\u00a0are now just two numbers in an ordered array.That is useful when I want to know how slow the slowest portion of requests tends to be.It is useless when the question is whether slow events arrive in clusters.Mathematically, any metric that is invariant under permutation cannot detect temporal clustering.Mean is permutation\u2011invariant.Variance is permutation\u2011invariant.Median is permutation\u2011invariant.p95\u00a0is&#8230;<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[],"tags":[],"class_list":["post-494430","post","type-post","status-publish","format-standard","hentry"],"_links":{"self":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/494430","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=494430"}],"version-history":[{"count":0,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/494430\/revisions"}],"wp:attachment":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=494430"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=494430"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=494430"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}