DEV Community

Devanshukoli
Devanshukoli

Posted on

My login endpoint had a 5.4 second P99. I was sure I knew why. I was wrong.

#signoz #opentelemetry #observability #wemakedevs

Found this completely by accident. I wasn't debugging anything, I was just poking around a SigNoz instance I'd self-hosted the night before, ahead of a hackathon build sprint. Opened the Service tab, and there it was.

skillbridge-api — P99: 5449.97ms. Error rate: 0.00%.

Zero errors is the annoying part. Nothing crashed, nothing threw, nothing would ever show up in an alert (not that I have any set up yet, but you get the idea). The app was doing exactly what it was told to do. It just took 5.4 seconds to do it.

Signoz Service Tab

Quick context if you're new here: SkillBridge is my side project, ed-tech app, Node/Express backend, Supabase for the DB, React frontend. I wired up SigNoz mostly to see what an actual OpenTelemetry setup looks like on a real app instead of a toy example. Wasn't expecting to find a real bug on day one. Found one anyway.

Trace #1: the login flow

Opened a trace for /api/auth/login:

  • Login — 873.95ms
  • Find User — 745.99ms
    • a GET out to Supabase — 322.09ms, with tls.connect / tcp.connect / dns.lookup nested inside it
  • Verify Password — 124.42ms

Signoz Trace Detail login trace id

124ms for bcrypt is fine, that's the whole point of bcrypt being slow. 746ms to fetch one user row is not fine.

The gotcha that had nothing to do with the bug but still cost me 10 minutes

Poking through other traces, I found a service literally named this:

unknown_service:C:\Users\Devanshukoli\scoop\apps\nvm\current\nodejs\nodejs\node.exe
Enter fullscreen mode Exit fullscreen mode

That's what SigNoz falls back to when you forget to set OTEL_SERVICE_NAME. It just uses the binary path instead. Not a big deal until you've got two or three scripts running and your service list turns into unreadable garbage. Fix is one line:

OTEL_SERVICE_NAME=skillbridge-worker node script.js
Enter fullscreen mode Exit fullscreen mode

Mentioning it because nobody tells you this until you hit it yourself, and then it's obvious.

The actual bug

That exact "unknown_service" trace is where the real evidence was sitting, which I only noticed because I'd already opened it to laugh at the naming issue. Seven back-to-back GET calls, each 300–600ms, none of them overlapping:

315.03ms
331.15ms
302.51ms
600.00ms
321.15ms
393.40ms
...
total: 2.52s
Enter fullscreen mode Exit fullscreen mode

Signoz Trace Details

Seven round trips to the same downstream service, one after another. Not "one query is slow." Just a straight-up queue that nobody asked for.

My first guess (wrong)

Staring at all those tls.connect spans showing up over and over, I figured: we're probably spinning up a new Supabase client on every request, so we keep paying a fresh handshake each time.

Reasonable guess. Took about a minute to check, and it died instantly:

let supabaseInstance: SupabaseClient | null = null;

export function getSupabaseClient(): SupabaseClient {
  if (supabaseInstance) return supabaseInstance;
  supabaseInstance = createClient(url, anonKey);
  return supabaseInstance;
}
Enter fullscreen mode Exit fullscreen mode

Already a singleton. My theory was just wrong, and I'm glad I checked the file instead of writing that guess down as fact.

What was actually going on

Found it in supabaseGetCurriculum:

const { data: tracks } = await supabase.from('skillbridge_tracks').select('*');
const { data: rawModules } = await supabase.from('skillbridge_modules').select('*').order('order', { ascending: true });
const { data: rawLessons } = await supabase.from('skillbridge_lessons').select('*').order('order', { ascending: true });
const { data: rawProjects } = await supabase.from('skillbridge_projects').select('*');
const { data: progressData } = await supabase.from('skillbridge_progress').select('*').eq('user_id', userId);
const { data: submissionsData } = await supabase.from('skillbridge_submissions').select('*').eq('user_id', userId);
Enter fullscreen mode Exit fullscreen mode

Six queries. None of them need each other's result. All six waiting in line anyway, because that's just how it comes out when you're writing a function at 1am and not thinking about what actually depends on what.

The fix 

const [
  { data: tracks },
  { data: rawModules },
  { data: rawLessons },
  { data: rawProjects },
  { data: progressData },
  { data: submissionsData },
] = await Promise.all([
  supabase.from('skillbridge_tracks').select('*'),
  supabase.from('skillbridge_modules').select('*').order('order', { ascending: true }),
  supabase.from('skillbridge_lessons').select('*').order('order', { ascending: true }),
  supabase.from('skillbridge_projects').select('*'),
  supabase.from('skillbridge_progress').select('*').eq('user_id', userId),
  supabase.from('skillbridge_submissions').select('*').eq('user_id', userId),
]);
Enter fullscreen mode Exit fullscreen mode

Where I have to be honest with you

Ran it. First trace after the fix: 1.49s total, and two of the calls clearly ran at the same time, no repeated handshake between them. I was pretty happy about that.

Trace image

Ran the exact same endpoint again a few minutes later. 2.44s. Three separate calls, each one paying its own tls.connect and tcp.connect again, like nothing carried over from the last request at all.

Trace lookups

Same code path. Same endpoint. Two completely different results. I wanted to go check the Service tab and see if P99 had actually moved over the last hour, and make sure my dev server had actually restarted with the new code instead of me testing against a stale process. Then my laptop crashed. An hour before this was due.

So that's where it ends for now. Not fixed-and-confirmed. Fixed-and-hopeful. Which, if I'm honest, is closer to how most of my debugging actually goes anyway.

What I'd tell past-me

  • Zero error rate doesn't mean zero problems. Nothing pages you for "technically correct but slow."
  • Check your theory against the actual code before you say it out loud. My first guess sounded smart and was completely wrong.
  • Promise.all isn't magic, it just relocates the bottleneck. I've now got a single query sitting around 1s that I still need to look at.
  • One good trace after a fix proves nothing on its own. Two traces disagreeing means you need the aggregate number, not another screenshot.

If you're building something and haven't wired up tracing yet, do it before you think you need it. I self-hosted SigNoz for this, and it found me a bug I wasn't even looking for on day one. Probably will for you too.

Top comments (0)