latest 5 build causes our initialisation script to take around 18 times longer than previous version

[erikv-hill-labs]

The latest 5 version which pulls in version 5.0.4 of firebird makes our main init script to build our database go from around 33 seconds to run, to almost 10 minutes.

If I change our compose.yaml to

db:
    image: firebirdsql/firebird@sha256:93458e3fb7023bfc4cd6cf855b05e373338ce56d1ffd13e05e883e7ad42e7136

Then it takes around 33 sconds to run through the scripts
when it is

  db:
    image: firebirdsql/firebird:5

It takes close to 10 minutes
I also tried 5-bookworm to see if it was the change to trixie that made the difference, but it also took the 10 minutes.

Is there any other debugging I can do to try to track down this issue?

[fdcastel]

@erikv-hill-labs could you share a small reproducible example?

I'll be glad to investigate, then. But for now I can't think in anything to explain this behavior.

[erikv-hill-labs]

@fdcastel I'll see if I can reproduce it with an example. I can't give our actual script as you could understand :)

[fdcastel]

I clearly understand. 👍🏻 -- I’m also making some attempts around here on my end.

[fdcastel]

@erikv-hill-labs Could you please confirm whether this issue still occurs for you when using the (current) firebirdsql/firebird:5.0.3 image?

This is a different image than the one you cited (firebirdsql/firebird@sha256:93458e3fb7023bfc4cd6cf855b05e373338ce56d1ffd13e05e883e7ad42e7136) -- which is a v1 image (v2 images were introduced recently).

[erikv-hill-labs]

@fdcastel Yes, the issue does occur using 5.0.3 from 3 days ago.

[fdcastel]

And with 5.0.3-bookworm? 😅

Sorry for all the questions, but without a reproducible example I’m basically guessing here.

I ran a few tests on my side, but nothing definitive came out of them.

Here’s what I have so far:

	v1 5.0.3 (fast)	v2 5.0.3 (slow)
base	debian 12.12	debian 13.4
glibc	2.36	2.41
libicu	libicu72	libicu76
libstdc++	12.2	14.2

That’s why I need you to test with 5.0.3-bookworm, so we can rule out trixie as a factor.

[erikv-hill-labs]

5.0.3-bookworm is also running slow

[fdcastel]

I could really use that repro right about now. 😄

Some other suggestions for you to try: while the slow init is running, run

• docker stats <container> in another terminal
• Firebird trace with statements ≥ 100 ms, plus plan + perf counters. Inside the running container:

  cat > /tmp/fb_trace.conf <<'EOF'
  database
  {
      enabled = true
      log_statement_finish = true
      print_plan = true
      print_perf = true
      time_threshold = 100
      max_sql_length = 2048
  }
  EOF
  
  fbtracemgr -se service_mgr -user SYSDBA -password masterkey \
             -start -name initrepro -config /tmp/fb_trace.conf > /tmp/init.trace &

Then run your init normally; the top entries in /tmp/init.trace will list every statement that took ≥ 100 ms with its plan and per-statement cost. Anonymising the literals from the slowest few would tell us a great deal without exposing the script.

[erikv-hill-labs]

I've run the trace and nothing of note appears in it.

The stats is showing the CPU is busy the whole time it is running the script.

I will try to create a reproduceable case this evening and hopefully get something you can use.

[erikv-hill-labs]

example-issue-40.zip

@fdcastel I have created a compose and init script based on the employee example db.

Using the old image it is practically instant to init the db
Using the new image it takes 8-9 seconds

[fdcastel]

Tracking PR: #41

@erikv-hill-labs I've published patched images to my fork's GHCR (FB 5.0.4, AMD64-only) with the one-line fix.

To swap into your existing compose.yaml, just change the image:

services:
  db:
    # was: image: firebirdsql/firebird:5
    image: ghcr.io/fdcastel/firebird:5
    # ...everything else unchanged

Or if you want to stay on bookworm specifically:

    image: ghcr.io/fdcastel/firebird:5-bookworm

Both contain the fix. If your init drops back from 8–9 s to "instant" / sub-second on your box, it would be the final piece of evidence and I'll merge upstream.

[erikv-hill-labs]

@fdcastel I can confirm that using that image restores the quick initialisation of the database.

Thank you! I will re-pull the updated version when it is released.

[fdcastel]

Thanks @erikv-hill-labs -- This nails it. I will be publishing the fixed images in the next few hours.

What's happening

The regression is in our v2 entrypoint. In v1, init scripts were piped:

*.sql)  cat "$f" | process_sql ;;

In v2 it became a redirect:

*.sql)  process_sql < "$f" ;;

That looks equivalent -- and on most filesystems it almost is.

But what I found is that isql reads stdin one byte per read() syscall (!?), so for your ~110 KB schema it issues ~95 600 single-byte reads in both modes. The number of syscalls is identical; what differs is the per-call latency:

• cat | isql: cat reads the file in big chunks, dumps it into a kernel pipe; isql reads single bytes from the pipe (in-memory, lock-free).
• isql < file: isql reads single bytes directly from the regular-file FD — every one going through the filesystem layer.

Thanks again for the clean repro. The right magnitude of the problem really only shows up on layered filesystems, which is why a synthetic test on native disk wasn't going to find it.