docker-pi-hole icon indicating copy to clipboard operation
docker-pi-hole copied to clipboard

Published 20 hours ago • verified publisher icon pi-hole

Pihole v6 takes more than 4 minutes to start on raspberry pi 3b

Open rohitagre opened this issue 1 year ago • 26 comments

This is a: Bug

Details

On restart of docker container, pihole loads queries from the long term database and it takes too long to finish this process. DNS resolution is unavailable during this time.

Related Issues

  • [x] I have searched this repository/Pi-hole forums for existing issues and pull requests that look similar

How to reproduce the issue

  1. Environment data
  • Operating System: Rasbian
  • Hardware: RasPi 3B
  • Kernel Architecture: aarch64
  • Docker Install Info and version:
    • Software source: Official Docker version 27.1.1, build 6312585
    • Supplimentary Software:
  • Hardware architecture:
  1. docker-compose.yml contents, docker run shell command, or paste a screenshot of any UI based configuration of containers here
# More info at https://github.com/pi-hole/docker-pi-hole/ and https://docs.pi-hole.net/
services:
  pihole:
    image: pihole/pihole:development-v6
    container_name: pihole-v6
    environment:
      # Change the Web UI Password:
      - FTLCONF_webserver_api_password=password
      - TZ=Asia/Kolkata
      - FTLCONF_dns_listeningMode=all
      - VIRTUAL_HOST=pihole.lan
      - VIRTUAL_PORT=80
    dns:
      - 127.0.0.1
    volumes:
      - "/home/pi/portainer/pihole6/etc-pihole:/etc/pihole"
      - "/home/pi/portainer/pihole6/etc-dnsmasq.d:/etc/dnsmasq.d"
    ports:
      - "53:53/tcp"
      - "53:53/udp"
    restart: unless-stopped
    networks:
      work:
        ipv4_address: 10.10.20.3

networks:
  work:
    name: work
    external: true
  1. any additional info to help reproduce
2024-08-07 10:54:57.725 IST [148M] INFO: ########## FTL started on 0022a4f6082d! ##########
2024-08-07 10:54:57.725 IST [148M] INFO: FTL branch: development-v6
2024-08-07 10:54:57.726 IST [148M] INFO: FTL version: vDev-7c00ea3
2024-08-07 10:54:57.726 IST [148M] INFO: FTL commit: 7c00ea38
2024-08-07 10:54:57.726 IST [148M] INFO: FTL date: 2024-07-29 18:17:47 +0200
2024-08-07 10:54:57.726 IST [148M] INFO: FTL user: pihole
2024-08-07 10:54:57.726 IST [148M] INFO: Compiled for linux/arm64/v8 (compiled on CI) using cc (Alpine 13.2.1_git20240309) 13.2.1 20240309
2024-08-07 10:54:59.036 IST [148M] INFO: 2 FTLCONF environment variables found (2 used, 0 invalid, 0 ignored)
2024-08-07 10:54:59.037 IST [148M] INFO:    [✓] FTLCONF_dns_listeningMode is used
2024-08-07 10:54:59.037 IST [148M] INFO:    [✓] FTLCONF_webserver_api_password is used
2024-08-07 10:54:59.043 IST [148M] INFO: Wrote config file:
2024-08-07 10:54:59.044 IST [148M] INFO:  - 148 total entries
2024-08-07 10:54:59.044 IST [148M] INFO:  - 134 entries are default
2024-08-07 10:54:59.044 IST [148M] INFO:  - 14 entries are modified
2024-08-07 10:54:59.044 IST [148M] INFO:  - 1 entry is forced through environment
2024-08-07 10:54:59.052 IST [148M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2024-08-07 10:54:59.053 IST [148M] WARNING: Insufficient permissions to set process priority to -10 (CAP_SYS_NICE required), process priority remains at 0
2024-08-07 10:54:59.060 IST [148M] INFO: PID of FTL process: 148
2024-08-07 10:54:59.063 IST [148M] INFO: listening on 0.0.0.0 port 53
2024-08-07 10:54:59.063 IST [148M] INFO: listening on :: port 53
2024-08-07 10:54:59.069 IST [148M] INFO: PID of FTL process: 148
2024-08-07 10:54:59.073 IST [148M] INFO: Database version is 19
2024-08-07 10:54:59.076 IST [148M] INFO: Database successfully initialized

<!-- import starts here -->
2024-08-07 10:55:50.360 IST [148M] INFO: Imported 351284 queries from the on-disk database (it has 1374429 rows)
2024-08-07 10:55:50.360 IST [148M] INFO: Parsing queries in database
2024-08-07 10:55:51.877 IST [148M] INFO:   10000 queries parsed...
2024-08-07 10:55:54.079 IST [148M] INFO:   20000 queries parsed...
2024-08-07 10:55:57.003 IST [148M] INFO:   30000 queries parsed...
2024-08-07 10:56:00.652 IST [148M] INFO:   40000 queries parsed...
2024-08-07 10:56:04.362 IST [148M] INFO:   50000 queries parsed...
2024-08-07 10:56:09.718 IST [148M] INFO:   60000 queries parsed...
2024-08-07 10:56:15.251 IST [148M] INFO:   70000 queries parsed...
2024-08-07 10:56:20.512 IST [148M] INFO:   80000 queries parsed...
2024-08-07 10:56:26.032 IST [148M] INFO:   90000 queries parsed...
2024-08-07 10:56:31.627 IST [148M] INFO:   100000 queries parsed...
2024-08-07 10:56:38.287 IST [148M] INFO:   110000 queries parsed...
2024-08-07 10:56:44.929 IST [148M] INFO:   120000 queries parsed...
2024-08-07 10:56:51.075 IST [148M] INFO:   130000 queries parsed...
2024-08-07 10:56:57.060 IST [148M] INFO:   140000 queries parsed...
2024-08-07 10:57:02.521 IST [148M] INFO:   150000 queries parsed...
2024-08-07 10:57:08.473 IST [148M] INFO:   160000 queries parsed...
2024-08-07 10:57:15.285 IST [148M] INFO:   170000 queries parsed...
2024-08-07 10:57:22.252 IST [148M] INFO:   180000 queries parsed...
2024-08-07 10:57:29.829 IST [148M] INFO:   190000 queries parsed...
2024-08-07 10:57:36.276 IST [148M] INFO:   200000 queries parsed...
2024-08-07 10:57:43.524 IST [148M] INFO:   210000 queries parsed...
2024-08-07 10:57:49.280 IST [148M] INFO:   220000 queries parsed...
2024-08-07 10:57:57.731 IST [148M] INFO:   230000 queries parsed...
2024-08-07 10:58:05.275 IST [148M] INFO:   240000 queries parsed...
2024-08-07 10:58:13.886 IST [148M] INFO:   250000 queries parsed...
2024-08-07 10:58:22.101 IST [148M] INFO:   260000 queries parsed...
2024-08-07 10:58:29.510 IST [148M] INFO:   270000 queries parsed...
2024-08-07 10:58:39.272 IST [148M] INFO:   280000 queries parsed...
2024-08-07 10:58:48.068 IST [148M] INFO:   290000 queries parsed...
2024-08-07 10:58:55.903 IST [148M] INFO:   300000 queries parsed...
2024-08-07 10:59:03.794 IST [148M] INFO:   310000 queries parsed...
2024-08-07 10:59:12.703 IST [148M] INFO:   320000 queries parsed...
2024-08-07 10:59:19.649 IST [148M] INFO:   330000 queries parsed...
2024-08-07 10:59:31.265 IST [148M] INFO:   340000 queries parsed...
2024-08-07 10:59:42.556 IST [148M] INFO:   350000 queries parsed...
2024-08-07 10:59:42.821 IST [148M] INFO: Imported 350224 queries from the long-term database
<!-- import ends here after almost 5 mins -->

2024-08-07 10:59:42.821 IST [148M] INFO:  -> Total DNS queries: 350224
2024-08-07 10:59:42.822 IST [148M] INFO:  -> Cached DNS queries: 129862
2024-08-07 10:59:42.822 IST [148M] INFO:  -> Forwarded DNS queries: 51045
2024-08-07 10:59:42.822 IST [148M] INFO:  -> Blocked DNS queries: 165277
2024-08-07 10:59:42.822 IST [148M] INFO:  -> Unknown DNS queries: 11
2024-08-07 10:59:42.822 IST [148M] INFO:  -> Unique domains: 5788
2024-08-07 10:59:42.822 IST [148M] INFO:  -> Unique clients: 56
2024-08-07 10:59:42.822 IST [148M] INFO:  -> DNS cache records: 24458
2024-08-07 10:59:42.823 IST [148M] INFO:  -> Known forward destinations: 2
2024-08-07 10:59:42.847 IST [148M] WARNING: Insufficient permissions to set system time (CAP_SYS_TIME required), NTP client not available
2024-08-07 10:59:42.847 IST [148/T718] INFO: NTP server listening on 0.0.0.0:123 (IPv4)
2024-08-07 10:59:42.847 IST [148/T719] INFO: NTP server listening on :::123 (IPv6)
2024-08-07 10:59:42.848 IST [148M] INFO: FTL is running as user pihole (UID 100)
2024-08-07 10:59:42.849 IST [148M] INFO: Reading certificate from /etc/pihole/tls.pem ...
2024-08-07 10:59:42.850 IST [148M] INFO: Using SSL/TLS certificate file /etc/pihole/tls.pem
2024-08-07 10:59:43.446 IST [148M] INFO: Restored 1 API session from the database
2024-08-07 10:59:43.518 IST [148M] INFO: Blocking status is enabled
2024-08-07 10:59:43.565 IST [148/T720] INFO: Compiled 0 allow and 0 deny regex for 56 clients in 1.5 msec

I just hope i am not missing any configuration parameters which is causing this.

Screenshot 2024-08-07 at 11 50 14 AM

These common fixes didn't work for my issue

  • [x] I have tried removing/destroying my container, and re-creating a new container
  • [x] I have tried fresh volume data by backing up and moving/removing the old volume data
  • [x] I have tried running the stock docker run example(s) in the readme (removing any customizations I added)
  • [x] I have tried a newer or older version of Docker Pi-hole (depending what version the issue started in for me)
  • [x] I have tried running without my volume data mounts to eliminate volumes as the cause

If the above debugging / fixes revealed any new information note it here. Add any other debugging steps you've taken or theories on root cause that may help.

rohitagre avatar Aug 07 '24 06:08 rohitagre

[x] I have tried running without my volume data mounts to eliminate volumes as the cause

Do you see the same 4 minutes even without the volumes?

rdwebdesign avatar Aug 07 '24 16:08 rdwebdesign

I have removed the volumes and i am now waiting for the database to populate. i will report back in 1 day

rohitagre avatar Aug 07 '24 18:08 rohitagre

Does not make any difference if i remove the Volumes. but i lose all customisations :( With Volumes : Time taken to load 60,000 queries : ~18 seconds Without Volumes : Time taken to load 60,000 queries : ~15 seconds

2024-08-08 17:58:39.417 IST [148M] INFO: Imported 69246 queries from the on-disk database (it has 69246 rows)
2024-08-08 17:58:39.417 IST [148M] INFO: Parsing queries in database
2024-08-08 17:58:40.164 IST [148M] INFO:   10000 queries parsed...
2024-08-08 17:58:41.918 IST [148M] INFO:   20000 queries parsed...
2024-08-08 17:58:44.137 IST [148M] INFO:   30000 queries parsed...
2024-08-08 17:58:46.744 IST [148M] INFO:   40000 queries parsed...
2024-08-08 17:58:49.189 IST [148M] INFO:   50000 queries parsed...
2024-08-08 17:58:52.047 IST [148M] INFO:   60000 queries parsed...
2024-08-08 17:58:54.955 IST [148M] INFO: Imported 69246 queries from the long-term database
2024-08-08 17:58:54.955 IST [148M] INFO:  -> Total DNS queries: 69246

I would also like to emphasise that pihole is running on a raspberry pi and it has only one SD card for all data, its not like docker volumes are on a different storage, so i don't think it should make any difference.

rohitagre avatar Aug 08 '24 12:08 rohitagre

Nothing to do with the slow loading, but these are not valid env vars:

      - VIRTUAL_HOST=pihole.lan
      - VIRTUAL_PORT=80

Two thoughts come to mind:

  • What class of SD card are you using?
  • Are you using an appropriate power supply for the Raspberry Pi?

PromoFaux avatar Aug 08 '24 15:08 PromoFaux

The env vars are for nginx proxy that I use for the web UI.

The SD card is class 10 and I am using official power supply for the pi.

$ sudo mmc csd read /sys/block/mmcblk0/device
type: 'SD'
card classes: 10 switch, 8 application specific, 7 lock card, 5 erase, 4 block write, 2 block read, 0 basic, 
capacity: 29.28Gbyte (31439454208 bytes, 61405184 sectors, 512 bytes each)

Speed test on SD card shows following

Write test

$ sudo dd if=/dev/zero of=./TestingFile bs=100M count=5 oflag=direct
5+0 records in
5+0 records out
524288000 bytes (524 MB, 500 MiB) copied, 40.99 s, 12.8 MB/s

Read test

$ sudo dd if=./TestingFile of=/dev/zero bs=100M count=5 oflag=dsync
5+0 records in
5+0 records out
524288000 bytes (524 MB, 500 MiB) copied, 23.0098 s, 22.8 MB/s

rohitagre avatar Aug 08 '24 15:08 rohitagre

Sorry, I mean to say they're not valid for v6. There is nothing inside the v6 container looking for those variables. I think there are equivalent proxy settings in FTL, though I do not have the documentation to hand right now.

I'll see if I can dig a 3b and a class 10 SD card out of my box of things and try to reproduce at some point - I have so far not experienced any such slow startup time, but then I am testing v6 on an x86 machine

PromoFaux avatar Aug 08 '24 16:08 PromoFaux

Sorry I don't think I was clear in my previous reply.

Those environment variables are used by another container running nginx-proxy which helps me in assigning local DNS domains to my containers so I don't have to use multiple ports https://github.com/nginx-proxy/nginx-proxy

rohitagre avatar Aug 08 '24 16:08 rohitagre

This issue is stale because it has been open 30 days with no activity. Please comment or update this issue or it will be closed in 5 days.

github-actions[bot] avatar Sep 08 '24 08:09 github-actions[bot]

@github-actions bot please reopen this issue  😉

rohitagre avatar Sep 13 '24 08:09 rohitagre

I have similar problem - for me it takes over 40s to start on my RPI 3

pihole  | 2025-02-25 00:15:28.062 CET [54M] INFO: PID of FTL process: 54
pihole  | 2025-02-25 00:15:28.065 CET [54M] INFO: listening on 0.0.0.0 port 53
pihole  | 2025-02-25 00:15:28.065 CET [54M] INFO: listening on :: port 53
pihole  | 2025-02-25 00:15:28.071 CET [54M] INFO: PID of FTL process: 54
pihole  | 2025-02-25 00:15:28.081 CET [54M] ERROR: SQLite3: recovered 16 frames from WAL file /etc/pihole/pihole-FTL.db-wal (283)
pihole  | 2025-02-25 00:15:28.083 CET [54M] INFO: Database version is 21
pihole  | 2025-02-25 00:15:28.110 CET [54M] INFO: Database successfully initialized

pihole  | 2025-02-25 00:16:13.413 CET [54M] INFO: Imported 60700 queries from the on-disk database (it has 18584595 rows)
pihole  | 2025-02-25 00:16:13.413 CET [54M] INFO: Parsing queries in database
pihole  | 2025-02-25 00:16:13.621 CET [54M] INFO:   10000 queries parsed...
pihole  | 2025-02-25 00:16:13.773 CET [54M] INFO:   20000 queries parsed...
pihole  | 2025-02-25 00:16:13.928 CET [54M] INFO:   30000 queries parsed...
pihole  | 2025-02-25 00:16:14.096 CET [54M] INFO:   40000 queries parsed...
pihole  | 2025-02-25 00:16:14.262 CET [54M] INFO:   50000 queries parsed...
pihole  | 2025-02-25 00:16:14.427 CET [54M] INFO:   60000 queries parsed...
pihole  | 2025-02-25 00:16:14.436 CET [54M] INFO: Imported 60552 queries from the long-term database

However the much worse part is that it seems like the DB is constantly "re-importing" or whatever. The DNS works for a few seconds and then it suddenly stops responding. The web GUI as well. I see 100% IO utilization of the SD card during that time. And it takes around 40s, so I think it is highly related to the import. Then it works for a few seconds and the cycle repeats. Nothing in the logs sadly.

The 2024.07.0 version I have migrated from works flawlessly, boots up within 20s.

petr-ujezdsky avatar Feb 24 '25 23:02 petr-ujezdsky

However the much worse part is that it seems like the DB is constantly "re-importing" or whatever. The DNS works for a few seconds and then it suddenly stops responding. The web GUI as well. I see 100% IO utilization of the SD card during that time. And it takes around 40s, so I think it is highly related to the import. Then it works for a few seconds and the cycle repeats. Nothing in the logs sadly.

I am confirming. My Pi-Hole 6 installation on a Synology NAS (not too powerful) is literally unusable because of these sudden freezes:

% nslookup bbc.com 192.168.1.11   
;; connection timed out; no servers could be reached

I am moving back to 2024.07.0.

alaz avatar May 21 '25 16:05 alaz

I have the same issue on a 3b+. Had to disable the database.

Even with an empty DB as a start it happens again after a couple of days/even hours...

This problem also leads to a slow query log - that eventually will take the web ui down in overload...

logopk avatar Jun 06 '25 13:06 logopk

Even with an empty DB as a start it happens again after a couple of days/even hours...

Oh, interesting. I was thinking that disabling the DB would help.

alaz avatar Jun 06 '25 19:06 alaz

Even with an empty DB as a start it happens again after a couple of days/even hours...

Oh, interesting. I was thinking that disabling the DB would help.

Oh I'm sorry, that was misleading. It works with a disabled DB.

The other suggested solution was to start from scratch and delete the DB file. That does not hold for a long time.

logopk avatar Jun 06 '25 21:06 logopk

The issue gets really bad once I reload the dns after updating data in my dnsmasq files (or any config in the UI that requires reload)

I have two use cases and I have not found a good way to update even through the api as any reload of the dns will take forever.

  • I'm updating IPs when I'm away from home and on VPN. I write the IP to a dnsmasq file, copy it to the pihole container and then reload the dns using the api.
  • setting an acme challenge through a dnsmasq file for my internal CA, again reloading the dns using the api. This is crucial as the acme dns-01 query has a timeout that hits!

(Just to prevent comments: I already have a failover DNS but that does not help in the acme case!)

I would like to ask, why the loading of the database blocks servicing DNS-queries? In v5 this worked flawlessly with querylogs for 30 days. There was the pihole restartdns command. Now already after a couple of hours and 100000+ records this blocks my internal network for 1min+.

logopk avatar Jun 16 '25 14:06 logopk

Around midnight it does an internal reload

tail: /var/log/pihole/FTL.log: file truncated
2025-06-17 00:33:37.701 CEST [50/T12350] INFO: Restarting FTL: API action request
2025-06-17 00:33:37.701 CEST [50M] INFO: Asked to terminate by "/usr/bin/pihole-FTL no-daemon" (PID 50, user pihole UID 1000)
2025-06-17 00:33:37.716 CEST [50/T12331] INFO: Terminating database thread
2025-06-17 00:33:37.786 CEST [50/T12334] INFO: Terminating timer thread
2025-06-17 00:33:37.879 CEST [50/T12332] INFO: Terminating GC thread
2025-06-17 00:33:38.433 CEST [50M] INFO: Finished final database update
2025-06-17 00:33:38.433 CEST [50M] INFO: Waiting for threads to join
2025-06-17 00:33:38.433 CEST [50M] INFO: Thread dns-client (2) is idle, terminating it.
2025-06-17 00:33:38.433 CEST [50M] INFO: Thread ntp-client (4) is idle, terminating it.
2025-06-17 00:33:38.433 CEST [50M] INFO: All threads joined
2025-06-17 00:33:38.437 CEST [50M] INFO: PID file emptied
2025-06-17 00:33:38.453 CEST [50M] INFO: Stored 2 API sessions in the database
2025-06-17 00:33:38.690 CEST [50M] INFO: ########## FTL terminated after 2h 43m 15s  (internal restart)! ##########
2025-06-17 00:33:38.702 CEST [50M] INFO: ########## FTL started on pi-hole! ##########
2025-06-17 00:33:38.702 CEST [50M] INFO: FTL branch: master
2025-06-17 00:33:38.702 CEST [50M] INFO: FTL version: v6.2.3
2025-06-17 00:33:38.702 CEST [50M] INFO: FTL commit: 88737f62
2025-06-17 00:33:38.703 CEST [50M] INFO: FTL date: 2025-06-10 20:44:58 +0200
2025-06-17 00:33:38.703 CEST [50M] INFO: FTL user: pihole
2025-06-17 00:33:38.703 CEST [50M] INFO: Compiled for linux/arm/v7 (compiled on CI) using cc (Alpine 14.2.0) 14.2.0
2025-06-17 00:33:39.744 CEST [50M] INFO: 13 FTLCONF environment variables found (13 used, 0 invalid, 0 ignored)
2025-06-17 00:33:39.744 CEST [50M] INFO:    [✓] FTLCONF_dns_expandHosts is used
2025-06-17 00:33:39.744 CEST [50M] INFO:    [✓] FTLCONF_dns_listeningMode is used
2025-06-17 00:33:39.744 CEST [50M] INFO:    [✓] FTLCONF_ntp_ipv4_active is used
2025-06-17 00:33:39.744 CEST [50M] INFO:    [✓] FTLCONF_misc_etc_dnsmasq_d is used
2025-06-17 00:33:39.744 CEST [50M] INFO:    [✓] FTLCONF_ntp_ipv6_active is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_dns_domain is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_webserver_api_password is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_webserver_port is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_dns_upstreams is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_dns_revServers is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_dns_domainNeeded is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_dns_dnssec is used
2025-06-17 00:33:39.745 CEST [50M] INFO:    [✓] FTLCONF_webserver_domain is used
2025-06-17 00:33:39.749 CEST [50M] INFO: Wrote config file:
2025-06-17 00:33:39.749 CEST [50M] INFO:  - 155 total entries
2025-06-17 00:33:39.749 CEST [50M] INFO:  - 139 entries are default
2025-06-17 00:33:39.749 CEST [50M] INFO:  - 16 entries are modified
2025-06-17 00:33:39.749 CEST [50M] INFO:  - 12 entries are forced through environment
2025-06-17 00:33:39.757 CEST [50M] INFO: Parsed config file /etc/pihole/pihole.toml successfully
2025-06-17 00:33:39.757 CEST [50M] INFO: PID file does not exist or not readable
2025-06-17 00:33:39.757 CEST [50M] INFO: No other running FTL process found.
2025-06-17 00:33:39.764 CEST [50M] INFO: PID of FTL process: 50
2025-06-17 00:33:39.772 CEST [50M] INFO: listening on 0.0.0.0 port 53
2025-06-17 00:33:39.792 CEST [50M] INFO: listening on :: port 53
2025-06-17 00:33:39.795 CEST [50M] INFO: PID of FTL process: 50
2025-06-17 00:33:39.798 CEST [50M] INFO: Database version is 21
2025-06-17 00:33:39.801 CEST [50M] INFO: Database successfully initialized
2025-06-17 00:34:12.931 CEST [50M] INFO: Imported 379587 queries from the on-disk database (it has 379587 rows)
2025-06-17 00:34:12.932 CEST [50M] INFO: Parsing queries in database
2025-06-17 00:34:13.115 CEST [50M] INFO:   10000 queries parsed...
2025-06-17 00:34:13.279 CEST [50M] INFO:   20000 queries parsed...
2025-06-17 00:34:13.440 CEST [50M] INFO:   30000 queries parsed...
2025-06-17 00:34:13.601 CEST [50M] INFO:   40000 queries parsed...
2025-06-17 00:34:13.758 CEST [50M] INFO:   50000 queries parsed...
2025-06-17 00:34:13.910 CEST [50M] INFO:   60000 queries parsed...
2025-06-17 00:34:14.066 CEST [50M] INFO:   70000 queries parsed...
2025-06-17 00:34:14.222 CEST [50M] INFO:   80000 queries parsed...
2025-06-17 00:34:14.382 CEST [50M] INFO:   90000 queries parsed...
2025-06-17 00:34:14.539 CEST [50M] INFO:   100000 queries parsed...
2025-06-17 00:34:14.693 CEST [50M] INFO:   110000 queries parsed...
2025-06-17 00:34:14.849 CEST [50M] INFO:   120000 queries parsed...
2025-06-17 00:34:15.006 CEST [50M] INFO:   130000 queries parsed...
2025-06-17 00:34:15.167 CEST [50M] INFO:   140000 queries parsed...
2025-06-17 00:34:15.329 CEST [50M] INFO:   150000 queries parsed...
2025-06-17 00:34:15.487 CEST [50M] INFO:   160000 queries parsed...
2025-06-17 00:34:15.643 CEST [50M] INFO:   170000 queries parsed...
2025-06-17 00:34:15.799 CEST [50M] INFO:   180000 queries parsed...
2025-06-17 00:34:15.955 CEST [50M] INFO:   190000 queries parsed...
2025-06-17 00:34:16.111 CEST [50M] INFO:   200000 queries parsed...
2025-06-17 00:34:16.269 CEST [50M] INFO:   210000 queries parsed...
2025-06-17 00:34:16.429 CEST [50M] INFO:   220000 queries parsed...
2025-06-17 00:34:16.591 CEST [50M] INFO:   230000 queries parsed...
2025-06-17 00:34:16.752 CEST [50M] INFO:   240000 queries parsed...
2025-06-17 00:34:16.913 CEST [50M] INFO:   250000 queries parsed...
2025-06-17 00:34:17.070 CEST [50M] INFO:   260000 queries parsed...
2025-06-17 00:34:17.227 CEST [50M] INFO:   270000 queries parsed...
2025-06-17 00:34:17.387 CEST [50M] INFO:   280000 queries parsed...
2025-06-17 00:34:17.548 CEST [50M] INFO:   290000 queries parsed...
2025-06-17 00:34:17.710 CEST [50M] INFO:   300000 queries parsed...
2025-06-17 00:34:17.875 CEST [50M] INFO:   310000 queries parsed...
2025-06-17 00:34:18.041 CEST [50M] INFO:   320000 queries parsed...
2025-06-17 00:34:18.202 CEST [50M] INFO:   330000 queries parsed...
2025-06-17 00:34:18.365 CEST [50M] INFO:   340000 queries parsed...
2025-06-17 00:34:18.523 CEST [50M] INFO:   350000 queries parsed...
2025-06-17 00:34:18.682 CEST [50M] INFO:   360000 queries parsed...
2025-06-17 00:34:18.844 CEST [50M] INFO:   370000 queries parsed...
2025-06-17 00:34:18.997 CEST [50M] INFO: Imported 379587 queries from the long-term database
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Total DNS queries: 379587
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Cached DNS queries: 359504
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Forwarded DNS queries: 16613
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Blocked DNS queries: 3373
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Unknown DNS queries: 26
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Unique domains: 1187
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Unique clients: 26
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> DNS cache records: 136
2025-06-17 00:34:18.997 CEST [50M] INFO:  -> Known forward destinations: 4
2025-06-17 00:34:20.222 CEST [50M] INFO: FTL is running as user pihole (UID 1000)
2025-06-17 00:34:20.223 CEST [50M] INFO: Web server ports:
2025-06-17 00:34:20.223 CEST [50M] INFO:   - 0.0.0.0:80 (HTTP, IPv4, OK)
2025-06-17 00:34:20.224 CEST [50M] INFO: Restored 2 API sessions from the database
2025-06-17 00:34:20.423 CEST [50M] INFO: Blocking status is enabled
2025-06-17 00:34:20.804 CEST [50/T15594] INFO: Compiled 2 allow and 0 deny regex for 26 clients in 271.9 msec
2025-06-17 00:34:27.432 CEST [50/T15593] INFO: Received 8/8 valid NTP replies from pool.ntp.org
2025-06-17 00:34:27.432 CEST [50/T15593] INFO: Time offset: 6.881952e-01 ms (excluded 0 outliers)

I assume due to logrotate?

logopk avatar Jun 17 '25 07:06 logopk

I assume due to logrotate?

I don't think so. It looks like something triggered the restart via API.

2025-06-17 00:33:37.701 CEST [50/T12350] INFO: Restarting FTL: API action request

2025-06-17 00:33:39.801 CEST [50M] INFO: Database successfully initialized 2025-06-17 00:34:12.931 CEST [50M] INFO: Imported 379587 queries from the on-disk database (it has 379587 rows)

@DL6ER is it expected to have no DNS resolution while the query database is importing?

yubiuser avatar Jun 17 '25 08:06 yubiuser

OK, I'll have an eye on it.

Currently at 640000 records. The downtime is at roughly 1:20 min.

logopk avatar Jun 17 '25 09:06 logopk

No automatic restart happened since yesterday.

Currently with 723492 log entries the reload takes 1:40 min.

logopk avatar Jun 18 '25 09:06 logopk

After 3 days the number has increased to 777652, reload takes 2:30 and

the query log takes almost 8 sec.

beware if you click twice or activate "live update", cpu and disk io gets high quickly:

grafana: CPU 18%-25% iotop: IO Rate 7.35M/s

Now dig lookups occasionally time out

Turning off live update brings CPU back down:

Image

IOs drop also:

Image

logopk avatar Jun 19 '25 22:06 logopk

After a week I did get frequent dig lookup failures. I enabled database debug. And I've found that every minute the storage of the query log takes between 15 and 20s.

During this time no queries are answered:

Di Jun 24 08:39:52 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:40:02 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:40:05 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:40:08 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:40:11 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:40:14 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:40:17 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:40:28 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:40:38 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:40:48 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:40:58 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:41:08 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:41:11 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:41:14 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:41:17 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:41:20 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:41:23 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:41:26 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:41:36 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:41:46 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:41:56 CEST 2025
local.mydomain
192.168.1.101
Di Jun 24 08:42:06 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:42:10 CEST 2025
local.mydomain
;; connection timed out; no servers could be reached
*********************************** ERROR 9
Di Jun 24 08:42:13 CEST 2025
local.mydomain
192.168.1.101

2025-06-24 08:40:00.175 CEST [48/T23646] DEBUG_DATABASE:          ---> OK
2025-06-24 08:40:00.175 CEST [48/T23646] DEBUG_DATABASE: dbquery: "UPDATE disk.counters SET value = value + 825 WHERE id = 0;"
2025-06-24 08:40:00.176 CEST [48/T23646] DEBUG_DATABASE:          ---> OK
2025-06-24 08:40:00.177 CEST [48/T23646] DEBUG_DATABASE: dbquery: "UPDATE disk.counters SET value = value + 9 WHERE id = 1;"
2025-06-24 08:40:00.177 CEST [48/T23646] DEBUG_DATABASE:          ---> OK
2025-06-24 08:40:18.333 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.domain_by_id
2025-06-24 08:40:18.336 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.client_by_id
2025-06-24 08:40:18.338 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.forward_by_id
2025-06-24 08:40:18.344 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.addinfo_by_id
2025-06-24 08:40:18.345 CEST [48/T23646] DEBUG_DATABASE: Exported 2 rows to disk.sqlite_sequence
2025-06-24 08:40:18.428 CEST [48/T23646] DEBUG_DATABASE: Exported 812 rows for disk.query_storage (took 18327.6 ms, last SQLite ID 5862240)
--
2025-06-24 08:41:00.084 CEST [48/T23646] DEBUG_DATABASE:          ---> OK
2025-06-24 08:41:00.085 CEST [48/T23646] DEBUG_DATABASE: Storing queries on disk WHERE id > 5862240 (max is 5861894) and timestamp < 1750747230.084646
2025-06-24 08:41:00.085 CEST [48/T23646] DEBUG_DATABASE: Accessing in-memory database
2025-06-24 08:41:18.999 CEST [48/T2840] DEBUG_DATABASE: Opening FTL database in count_messages() (/app/src/database/message-table.c:1030)
2025-06-24 08:41:19.184 CEST [48/T2840] DEBUG_DATABASE: Closing FTL database in count_messages() (/app/src/database/message-table.c:1059)
2025-06-24 08:41:25.283 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.domain_by_id
2025-06-24 08:41:25.284 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.client_by_id
2025-06-24 08:41:25.287 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.forward_by_id
2025-06-24 08:41:25.297 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.addinfo_by_id
2025-06-24 08:41:25.300 CEST [48/T23646] DEBUG_DATABASE: Exported 2 rows to disk.sqlite_sequence
2025-06-24 08:41:25.317 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows for disk.query_storage (took 25232.5 ms, last SQLite ID 5861428)
--
2025-06-24 08:42:00.272 CEST [48/T23646] DEBUG_DATABASE:          ---> OK
2025-06-24 08:42:00.272 CEST [48/T23646] DEBUG_DATABASE: dbquery: "UPDATE disk.counters SET value = value + 661 WHERE id = 0;"
2025-06-24 08:42:00.272 CEST [48/T23646] DEBUG_DATABASE:          ---> OK
2025-06-24 08:42:00.273 CEST [48/T23646] DEBUG_DATABASE: dbquery: "UPDATE disk.counters SET value = value + 4 WHERE id = 1;"
2025-06-24 08:42:00.273 CEST [48/T23646] DEBUG_DATABASE:          ---> OK
2025-06-24 08:42:14.130 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.domain_by_id
2025-06-24 08:42:14.131 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.client_by_id
2025-06-24 08:42:14.133 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.forward_by_id
2025-06-24 08:42:14.138 CEST [48/T23646] DEBUG_DATABASE: Exported 0 rows to disk.addinfo_by_id
2025-06-24 08:42:14.138 CEST [48/T23646] DEBUG_DATABASE: Exported 2 rows to disk.sqlite_sequence
2025-06-24 08:42:14.160 CEST [48/T23646] DEBUG_DATABASE: Exported 679 rows for disk.query_storage (took 14069.6 ms, last SQLite ID 5862786)

Extending the database.DBinterval would be one solution but together with the even longer DB reload after a restart, I chose to disable the database alltogether.

Since then all queries go through and restart time is acceptable.

logopk avatar Jun 24 '25 12:06 logopk

Extending the database.DBinterval would be one solution but together with the even longer DB reload after a restart, I chose to disable the database alltogether.

Since then all queries go through and restart time is acceptable.

I've had to resort to the same method to keep PiHole running on my A+.

I rolled back to a earlier release which seemed to be working fine until today, to which CPU load was just too much and DNS queries failed over all the clients. I removed the container and tried the latest release. No improvement.

Bypassed blocking, went into system settings and set database.maxDBdays to 0. Load instantly fell down to acceptable levels.

Operating System: Raspbian GNU/Linux 11 (bullseye) Hardware: RaspberryPi A+ Kernel Architecture: armv6l Docker Install Info and version: Software source: Docker Engine - Community, 20.10.10

DXPetti avatar Jul 14 '25 01:07 DXPetti

We have had to make the same modifications to keep our systems running as well. The real issue comes down to the fact that on each restart or reload it will parse all queries and create significant io wait on any SD card regardless of class if the database is big enough.

The name of this entire project derives from raspberry pi and the vast majority of those still use an SD card as their sole "disk"

I think this issue would be better serviced over at the main pihole project to move parsing the queries to a maintenance job that only happens so often or slowly post boot.

PhilThurston avatar Aug 04 '25 19:08 PhilThurston

I think this issue would be better serviced over at the main pihole project to move parsing the queries to a maintenance job that only happens so often or slowly post boot.

Pi-hole parses the last 24h of the on-disk database on startup to be aware of its recent history. You can disable this with the database.DBimport setting.

yubiuser avatar Aug 04 '25 20:08 yubiuser

You still don't get the point. It should do this in a separate task and non-blocking. That would speed up startup. Each restart of DNS, reload or many changes of settings suffers also from this problem. I don't think it is necessary to always clear the memory.

IIRC v5 did not have this problem.

logopk avatar Aug 04 '25 20:08 logopk

There is hope: https://github.com/pi-hole/FTL/issues/2599#issuecomment-3175286431

alaz avatar Aug 11 '25 15:08 alaz