DEV Community

Cover image for Anatomy of 32 Days
Anton Brilliantov
Anton Brilliantov

Posted on

Anatomy of 32 Days

Cover reading Anatomy of 32 Days, with 32 on a vermilion slab, the figure 24 of 26 answerable before the code, and four columns 32, 11, 9 and 7 for the days down to the ones with traced runs

Every number here was cheap to collect and late to arrive. That gap is the whole story.


๐Ÿ‘‹ Hi, I'm Anton - a software engineer working mostly in PHP/Symfony and Go, currently carving a live PHP monolith into Go services. The seven parts before this one each took one angle on a single write path that left the monolith. This one is the ledger: the same 32 days read as one timeline, with every figure in one place and a link to the part that unpacks it. Running notes live on my GitHub: github.com/brilliant-almazov.

This is how I do it right now, with the price attached - maybe you already do it better, maybe you'd do it another way.


The path in one paragraph

A user saves a set of matching rules; every domain under that account gets marked by them. Four participants: the Go API gateway as the only door from outside, the rule-set-markup service which takes the write and folds the cascade, the domain-rule-map service which owns rule-set identity and recalculates the map, and PostgreSQL behind them - the monolith's database for the rule data, the identity service's own for identity.

One user action, four processes, two databases. Accepting that as working took 32 days, and this is what was inside them.

The series system map with every part lit - the UI, the Go API gateway, the rule-set-markup service, the domain-rule-map service, the acceptance repository and the shared gRPC contract layer - and only the PHP monolith dimmed

What "32 days" actually contains

The headline number is the least useful one in the set, so it is worth breaking before anything is built on it.

  DAYS   32 โ”คโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ  the acceptance timeline
            โ”‚        โ–ผ โˆ’21  automated verdicts only: pass/fail per case, no numbers, no traces
         11 โ”คโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ
            โ”‚        โ–ผ โˆ’2   two days with no verdict at all โ€” the wrong thing was under test
          9 โ”คโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ
            โ”‚        โ–ผ โˆ’2   days inside the detailed window with no runs
          7 โ”คโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ  โ—„ days with detailed, traced runs
  โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”ดโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€
  MINUTES inside those 7 days โ€” 985 total = 16 h 25 min
    day 1 โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ 178      day 5 โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ 179
    day 2 โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ    150      day 6 โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ            77
    day 3 โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ         102      day 7 โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ           89
    day 4 โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ 210   โ—„ one run alone = 120
Enter fullscreen mode Exit fullscreen mode

Animated bars shrinking from 32 days of the acceptance timeline to 11 without the verdicts-only days, 9 without the days with no verdict, and 7 days with traced runs, with a note: 985 minutes = 16 h 25 min, 34 runs

34 runs across the period, 28 of them numbered. Duration was recorded for 29 of the 34: mean 34 minutes, longest 2 hours, shortest 2 minutes. So the honest version of the headline is not "32 days of testing" - it is 16 hours 25 minutes of measured work, spread over 7 days, inside a 32-day window.

I am starting here because every ratio later in this article has one of these denominators in it, and the wrong denominator turns a modest finding into a dramatic one for free.

Three windows, three instruments

The 32 days are not one measurement. They are three, taken with different instruments, and no line crosses between them honestly.

  window 1   before day 0        no acceptance artefacts exist at all
                                 behaviour reconstructed from migrations, commits, docs
  window 2   day 0 โ€ฆ day 21      automated verdicts per case, per deploy tag
                                 pass / fail, and nothing else โ€” no timings, no traces
  window 3   day 21 โ€ฆ day 32     traced runs: timings, state dumps, statement text
                                 the numbered defect registry starts on day 25
Enter fullscreen mode Exit fullscreen mode

Three window tiles joined by dashed arrows - before day 0, no artefacts; day 0 to 21, verdicts only; day 21 to 32, traced runs - with a note: a comparison across two windows compares instruments, not systems

Which produces the reading rule I put on every chart in this material:

Comparing across those windows compares methods of observation, not states of the system.

Two more caveats travel with it, and they are in every part of this series for the same reason: round-trip time to the environment sits at a steady 220-260 ms regardless of endpoint, so it is never part of anyone's work; and a share is never published without its absolute value - 440.0 ms ยท 61 %, never 61 % on its own.

Day one of the detailed window: three objects, everything passes

For the first weeks the checks ran against a playground of three objects. The runs were honest - real requests, real assertions, real data written and read back - and everything passed.

Then a run went across everything the environment held:

  playground              3 objects        everything passes
  full sweep            276 objects        the active-set registry is EMPTY for 210 of them
  later sweeps          392 objects        392 of 392 covered; 129 map rows of 2 329
                                           carry neither rule set nor priority (5.5 %)
Enter fullscreen mode Exit fullscreen mode

Two halves: the playground, 3 objects, everything passes; the full sweep, 210 of 276 with an empty registry; a note below reads later: 392 of 392, 129 of 2 329 rows bare

Nothing was fixed between the first two lines. The system was in the same state; what changed is that it could be asked - the services had grown read endpoints that describe state: the input snapshot, the rule set in effect, the pointer to the active set, the stored map page by page.

That is Part 2 - A Service That Cannot Explain Itself Can Only Be Guessed At. It is the earliest thing in this timeline in the causal sense: nothing else here was findable before those four reads existed.

The argument about who was slow

The next thing the traced window settled was an argument that had been running on opinions. A single write, end to end: 121 spans, four services, 1 256.9 ms on the client's stopwatch. The blame sat on the write service, because that is the address on the envelope.

Read as nesting rather than as a sum:

  client wait                                       1 256.9 ms   100 %
  โ”œโ”€โ”€ transport, client โ†” environment                  244.9      19.5 %   not ours
  โ””โ”€โ”€ four services at work                          1 012.0      80.5 %
      โ””โ”€โ”€ the suspected service, own zone                87.4       7.0 %
          โ”œโ”€โ”€ own work                                    1.4
          โ””โ”€โ”€ waiting on PostgreSQL                      86.0      98.4 % of its zone
Enter fullscreen mode Exit fullscreen mode

Three number tiles: 1 256.9 ms on the client's stopwatch, 87.4 ms in the blamed service's zone, 1.4 ms of its own code, with a stamp reading 97.2 % of a rejection is not ours

87.4 ms of 1 256.9 - 7.0 %, and 98.4 % of that is waiting on the database. The code itself accounts for 1.4 ms.

The cheapest confirmation in the whole set came from a request that was rejected as invalid: server work 6.6 ms, database 0.0 ms, client stopwatch 231.8 ms. Nothing computed, nothing stored, and 97.2 % of the call still happened outside our code.

And when the shape of one read was fixed, the same three-build comparison showed why the unit matters: database round trips went 92 to 7, database time 440.0 to 31.8 ms - a factor of 14 - while the network never moved. By share alone the network went from a third of the call to 88 % of it and reads as a catastrophe. In milliseconds, everything we own fell and the rest stood still.

Full breakdown, including the zone we still cannot measure: Part 1 - Most of Your Latency Is Not Your Code.

The account that did not fit

The same instrument answered a question nobody had asked before shipping: how much work is one caller allowed to order?

One object addressed directly is 121 spans and 53 database round trips, 11 of them repeats. One account addressed at the top, with 366 children below it, is 10 822 spans - roughly 30 spans per child, derived by dividing one measured total by one measured count.

The deadline on that call is a constant 20 seconds. The work behind it is a line. On one observed run the caller was cut off at 20.26 s and the work carried on for another 8.7 s, committing successfully at 28.96 s:

  0 s                                  20.26 s               28.96 s
  โ”œโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”คโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”ค
  โ”‚  work in progress                     โ”‚  8.7 s more work  โ”‚
                                          โ”‚
                          caller is told: the call failed
                                                              โ”‚
                                          database holds: the write landed
Enter fullscreen mode Exit fullscreen mode

Around 253 children is where the endpoint stops fitting, and how many accounts sit above that line is a product fact nobody had written down. In aggregate it showed up as deadline failures on 13 of 76 objects, then 27 of 76 after a change meant to help. The whole slope, and why optimisation moves the crossing point rather than removing it, is Part 5 - The Client Decides How Much Work You Do.

Animated waterfall of one call: the caller's bar stops with a warning, cut off at 20.26 s; the work bar runs on, committed at 28.96 s; an amber bar after the cut reads 8.7 s more; a note reads 366 children, 10 822 spans, a constant 20 s

The value nobody owned

The longest-lived defect of the period had no code to blame. A rule is saved, the response is 200, the read shows the new set - and the engine keeps marking by the old one. Eight rounds thirty seconds apart, four minutes of the two answers disagreeing, no error anywhere.

Six iterations, the record of the whole timeline. The analysis that explained it took an afternoon:

  • the value lives in four carriers across two databases, and there is no foreign key between them - there cannot be, they belong to different services;
  • the right to write it had moved seven times in 48 days;
  • in one of those states, two days long, it belonged to nobody;
  • and the state was produced by two commits, same day, two repositories, each correct on its own, which together formed a circle: a freshly written set has no map rows, so it can never become active.

Four number tiles for the value nobody owned: 6 iterations, the record; 4 carriers in 2 databases; 7 moves in 48 days; 2 days owned by nobody; with a stamp reading two correct commits, one circle

No review inside either repository could have caught it: each diff was right, and the contradiction lived on the seam. Part 3 - Nobody Owned the Value is that afternoon written out, including the detector that catches the class forever: two reads and an equality check, run on all 392 objects.

The contract that could not say zero

While that ran, a second class was producing numbers of its own. A priority that was stored, correct and impossible to present, because the strongest priority in this system is written as 0 and on the wire 0 looks exactly like a field nobody set. Both sides were locally correct: the producer omits zero values by the rules of the format, the consumer treats an absent field as unset.

Eight of the 26 numbered defects were defects of contract shape - the largest single class in the registry, and not one of them was a computation error. The same field's own history: removed from the contract, put back about 45 days later, and pinned down with an explicit meaning for zero on day 91.

What made it observable was not an assertion on a response - every response was correct throughout - but a count over stored state: map rows carrying no priority at all, 27 to 41 to 0.

A dark JSON card: stored priority 0, on the wire an empty object - highlighted - the consumer reads priority as unset, bare rows 27 to 41 to 0, with a note: 8 of 26 were contract shape

And its quieter twin: when two rules tie, which wins? Nobody had ever decided. The behaviour was deterministic - first match in array order - and it had held as a norm for 17 months as a property of how a loop was written. Part 6 - Zero Is Not Absent, and Nobody Wrote the Order Down.

The baseline that moved

The method for accepting the new write path was parity: run both implementations on the same input, compare field by field. That is a sound method exactly once - when the reference stands still.

On one day the same input went through nine iterations, and the size of the cascade the two sides produced went 2, then 258, then 2, then 8 rows. The reference was changing its own definition mid-day, and it was internally inconsistent too: one identifier came back as a number in one field and as a string in another. Three times out of nine the new implementation turned out to be the correct one.

Four columns for one input: 2 rows, 258 rows in red, 2 rows, 8 rows, with a stamp reading new side right 3 of 9

Underneath sat the same failure in three different disguises:

  • a 502 returned after the row was committed;
  • a 200 completed on a row that had been silently deleted;
  • a 504 at 20.26 s on a write that went through.

A dark log card of three responses against the database: 502 with the row committed; 200 completed with the row silently deleted, highlighted; 504 at 20.26 s with the write gone through; a note reads two storages, no shared tx

None of them is a lie by the transport. With two storages and no shared transaction, a response code reports that the call arrived and its own transaction closed - and nothing about what is in the database. Then the parity work was erased in one line by a correct decision: the old write endpoint would be removed entirely. Part 4 - Parity Against a Moving Baseline has the full accounting, including the one thing that was missing - the date the comparison would expire.

The ledger

Everything above, as counts.

  26 numbered defects
     16   closed as real defects            (by subtraction from the four rows below)
      5   declared normal behaviour
      3   still open at the end of the period
      2   withdrawn as false

  39 defect-iterations between those 26 numbers      longest single defect: 6 iterations
   8 false alarms in total, of which one is a false PASS - a check that ran zero comparisons
Enter fullscreen mode Exit fullscreen mode

A grid of 26 cells: 16 green closed as real, 5 teal declared normal, 3 amber still open, 2 red withdrawn as false, with the counts beside it and a stamp reading 1 false pass: 0 comparisons

Two rows are worth more than the rest.

Three still open at the end of the period, and their wording is the giveaway: rule order is not provable; cursor paging says "more" and returns no token; an asynchronous rebuild lands in tens of seconds - or does not. None of them is "the code is wrong". All three are "the system cannot demonstrate the property being asked about".

One false PASS. A probe sent a single value to an endpoint that requires a list, got a 422, took the empty decision list as agreement and printed PASS 24, FAIL 3. Two builds were accepted on a line that had performed zero comparisons. A false FAIL creates work. A false PASS removes the check and leaves the report looking identical.

What a document would have caught

This is the number I keep from the whole period, and the one I am least comfortable with.

   26 numbered defects
   โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ  26
             โ”‚
             โ–ผ  step 1 โ€” the specification names WHO WRITES this value
   โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ                18  left
             โ”‚
             โ–ผ  step 0 โ€” endpoint and fields taken from the contract, not from memory
   โ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆโ–ˆ                              13  left
             โ”‚
             โ–ผ  steps 2/3/4/6 โ€” actual measurement against a live system
   โ–ˆโ–ˆ                                             2  โ—„ one conditional, one unobservable
Enter fullscreen mode Exit fullscreen mode

Three number tiles: 24 of 26 answerable on paper, 92 %; 21 of 39 iterations die on one question; 2 need a live run; with a note: who is allowed to write this value?

24 of 26 - 92 % - would have been removed by acceptance written before the code, and 21 of 39 defect-iterations die on one question: who is allowed to write this value? That question is answered by reading a document. It is an estimate over the registry rather than an experiment, and I publish it as one - but even halved it says the same thing.

What it cost, and the number I never took

The bill is not "we wrote buggy code". It is the cost of finding out what was wanted:

  requirements with two defensible readings            23
  reversals of decisions already implemented            7      in 5 of 6, the code matched
                                                               the specification of its day
  iterations spent finding out rather than fixing   ~13 of 27  (estimated over intervals)
  iterations of briefs written and discarded            15     within a day
  brief files accumulated in the repository            289     137 of them in 33 numbered sets
  write-ups of my own acceptance mistakes               28     5 of them repeated, 1โ€“6 days apart
  โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€
  days with a measurement of money or tokens             0
Enter fullscreen mode Exit fullscreen mode

A torn paper receipt for 32 days of finding out: 23 ambiguous requirements, 7 reversals of decisions, about 13 of 27 iterations finding out, 15 brief iterations discarded, 289 brief files, 28 mistake write-ups; cost measured 0 days, with a stamp reading never priced

The last row is the one I would fix first if I were starting again. Every duration in this article was recorded; not one day carries a figure for what the automated work cost in tokens or money. That means everything here is a claim about what the arrangement found, and nothing here is a claim about whether it was worth it. Those are different claims and I can only make the first.

The row above it is the second-cheapest lesson: 5 of 28 mistakes repeated within one to six days, every one of them already written up in prose. A rule that lives only in a postmortem is re-derived by whoever reads it next, which is to say never - and an automated executor never reads it at all. What stopped the repeats was moving each rule into the two places that are read on every run: the brief, as a numbered constraint, and the check, as an assertion that fails.

The arrangement that produced most of the numbers above - one automated pass pointed at the output of another, told to instrument the zone with no spans and report back - is Part 7 - One Executor Checking Another Executor's Work.

Seven readings, one per part

If the timeline collapses to seven sentences, these are the seven:

  1. A service is judged by its own span, not by the client's stopwatch. 87.4 ms of 1 256.9 - and 97.2 % of a rejected call is not our code. -> Part 1
  2. A service that cannot state what its answer should be can only be guessed at. Three objects passed; 276 objects had 210 empty registries, and nothing had changed in between. -> Part 2
  3. A value with no named owner does not have a bug - it has an unfinished analysis. Four carriers, two databases, seven moves of the write right in 48 days, two of those days belonging to nobody. -> Part 3
  4. A comparison is a test only while the reference stands still. Nine parity runs in one day, a cascade of 2, 258, 2 and 8 rows for the same input, and a comparison with no expiry date. -> Part 4
  5. A synchronous answer over work the caller sizes is a promise the caller gets to break for you. A constant 20-second deadline against a cost that is linear in 366 children. -> Part 5
  6. A field that cannot separate "absent" from "zero" is two facts sharing a slot. Eight of 26 defects were contract shape; a tie-break rule held as a norm for 17 months because it lived in a loop. -> Part 6
  7. A second automated pass earns its cost only if it can add a measurement the first one never had. 92 database round trips on a call that needs 7, reported as 200 OK in every column. -> Part 7

And the one that only appears when they are read together: the split did not create these defects, it made them expressible. A single process can hold an unstated ownership rule, an unstated tie-break and an unstated capacity limit indefinitely, because there is no boundary at which the omission has to be declared. Two services cannot.

A four-panel strip: what we did, 3 objects passed in the playground; what broke, 26 numbered defects, 39 iterations; why, 4 sentences never written; what now, 24 of 26 answerable on paper

What none of this proves

Being explicit, because a ledger invites conclusions it cannot support.

It does not say microservices are worse than a monolith, or better. It does not say anything got faster after the split - the instruments changed inside the window, and the earlier stretch has no numbers to compare against. It does not price anything: no money, no person-hours, no token counts. It does not say anything about the reliability of anyone's production system; every figure here comes from a test environment.

What it does support is narrower: on this path, in this period, 24 of 26 defects were answerable before anything ran, and the four questions that would have answered them fit on one page.

The multiplier line

Nine parity runs in a day, a sweep of 392 objects per build, a trace folded into a table and diffed against yesterday's - all of that was cheap because it was automated, and none of it would have been affordable by hand. What automation never supplied was a single one of the sentences that were missing: who may write this value, what absent means for this field, how large a caller is allowed to be, which side of a comparison is entitled to be right. Fast iteration multiplies the definitions that exist in writing. Where a definition is missing, it multiplies the circling instead - and produces, very precisely and very confidently, 39 iterations of a description where four written sentences would have done.


Anatomy of a service split - Part 8. That closes this set. The obvious hole in it is the last row of the bill: 985 minutes of recorded duration and not one day with a cost figure attached. The next thing I measured was exactly that - what the automated work itself bills, per session, in tokens and in money, before any of it produces a line of output.

If you do this better, tell me which of your defects you can honestly say a document would have caught. If you have been through this, what did your own ledger look like when you counted the iterations rather than the tickets? If you see it differently, say where writing the requirement down first costs more than it returns. How is it solved on your side, and what broke there?

Top comments (0)