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

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?

@erikv-hill-labs

@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.

@fdcastel

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

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

@erikv-hill-labs

@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).

@fdcastel

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

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.

5.0.3-bookworm is also running slow

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.

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.

@fdcastel

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

@erikv-hill-labs

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.

@fdcastel

@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.

@erikv-hill-labs

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.

fix(entrypoint): pipe *.sql files into isql to avoid 1-byte read ampl…

@erikv-hill-labs

@erikv-hill-labs the Docker Hub images have been fully rebuilt and pushed, so the entrypoint fix from #41 is now live across all stable tags (multi-arch, amd64 + arm64). A fresh docker pull should pick it up.

Navigation Menu

Repository navigation

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

What's happening

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

fdcastel commented on Apr 30, 2026

erikv-hill-labs commented on Apr 30, 2026

fdcastel commented on Apr 30, 2026

fdcastel commented on Apr 30, 2026

erikv-hill-labs commented on Apr 30, 2026

fdcastel commented on Apr 30, 2026

erikv-hill-labs commented on Apr 30, 2026

fdcastel commented on May 1, 2026

erikv-hill-labs commented on May 1, 2026

erikv-hill-labs commented on May 1, 2026

fdcastel commented on May 1, 2026

erikv-hill-labs commented on May 1, 2026

fdcastel commented on May 1, 2026

What's happening

fdcastel commented on May 1, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions