sg-1100 DHCP lease status page load time

stephenw10

Hmm, it looks like it's trying to load something huge. But you only habe ~100 clients total?

Are they all pulling multiple leases?

When it does load how many leases are there?

Steve

gabric098

@stephenw10
Hi Steve,
thanks for your reply.
This morning the network is pretty quiet, I have only 14 leases + 4 static IP assigned and online.
The page took 2 minutes to load.

I had a look to the system logs and I noticed that in the DHCP log I see these logs repeating (not sure if it's relevant):

Feb 19 09:37:40	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 6
Feb 19 09:37:32	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 8
Feb 19 09:37:23	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 9
Feb 19 09:37:03	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 20
Feb 19 09:36:53	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 10
Feb 19 09:36:49	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 4
Feb 19 09:36:47	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Feb 19 09:36:45	dhclient	20352	DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Feb 19 09:36:30	dhclient		FAIL
Feb 19 09:36:30	dhclient	20352	No working leases in persistent database - sleeping.
Feb 19 09:36:30	dhclient	20352	No DHCPOFFERS received.

Thanks,
Gab

stephenw10

That's the pfSense WAN trying to refresh it's lease against the last DHCP server it was using and failing. That should be unrelalted to the lease list from the pfSense's own dhcp server.

Try running in an SSH window top -aSH while you open that page. What process is it waiting for? Is anything using all the available CPU at that point?

Steve

gabric098

@stephenw10
Hi Steve,
I've tried and the process using most of the CPU is php-fpm which I suspect it's expected as PHP is generating the page.
The process stays at the top using 98-100% of the CPU until the page is rendered.
Loading other web interface pages is pretty snappy and the the php process doesn't go over 25%.

Screen Shot 2021-02-20 at 21.14.35.png

Note: I don't have any packages installed apart from
https://github.com/pfsense/FreeBSD-ports/commits/devel/sysutils/pfSense-pkg-Cron

Thanks,
Gab

stephenw10

Hmm.
The cron package dies nothing but expose the existing cron jobs unless you have added more so I wouldn't expect that to do anything.

Since it runs for so long you can probably catch it running:
ps -auxwwd
That might show you what php is actually trying to do there.

You might also upgrade to 21.02 since if this is some bug you're hitting it will only be patched there. Be sure to backup your config from 2.4.5p1 first though so you can revert to that if needed.

Steve

gabric098

@stephenw10
Hi Steve,
I did what you suggest and I see php process launching the following command:

/var/dhcpd/var/db/dhcpd.leases | /usr/bin/awk '{ gsub("#.*", "");} { gsub(";", ""); print;}' | /usr/bin/awk 'BEGIN { RS="}";} {for (i=1; i<=NF; i++) printf "%s ", $i; printf "}\\n";}'

Now, I don't know what's the expected size of the dhcp.leases file but in my case is pretty big (~22MB).

#ls -las /var/dhcpd/var/db/dhcpd.leases
21376 -rw-r--r--  1 dhcpd  _dhcp  21853501 Feb 21 21:33 /var/dhcpd/var/db/dhcpd.leases

I assume php is making some manipulation of the data returned by the shell command and that might cause the delay in page load.

I had a look to the dhcpd.leases file and it contains very old leases like:

starts 0 2020/05/03 13:44:12;
  ends 0 2020/05/03 14:03:57;
  tstp 0 2020/05/03 14:03:57;
  cltt 0 2020/05/03 13:44:12;

From what I understand this file should be emptied from time to time but the logic behind it it's pretty obscure to me.
This is the content of the db folder:

#ls -las /var/dhcpd/var/db/
total 64340
    4 drwxr-xr-x  2 dhcpd  _dhcp       512 Feb 21 21:42 .
    4 drwxr-xr-x  4 dhcpd  _dhcp       512 May 16  2019 ..
21376 -rw-r--r--  1 dhcpd  _dhcp  21850596 Feb 21 21:42 dhcpd.leases
    4 -rw-r--r--  1 dhcpd  _dhcp       502 Dec  7  2019 dhcpd.leases.1575755403
    4 -rw-r--r--  1 dhcpd  _dhcp       502 Dec  7  2019 dhcpd.leases.1575755854
    4 -rw-r--r--  1 dhcpd  _dhcp       502 Dec  7  2019 dhcpd.leases.1575759309
21568 -rw-r--r--  1 dhcpd  _dhcp  22052731 Jun 20  2020 dhcpd.leases.1592644918
21376 -rw-r--r--  1 dhcpd  _dhcp  21854188 Feb 21 21:42 dhcpd.leases~
    0 -rw-r--r--  1 dhcpd  _dhcp         0 May 16  2019 dhcpd6.leases

Thanks,
Gab

stephenw10

22MB seems huge for 100 clients. I'm not surprised it's slow opening that.

Have you looked inside that file? Hard to imagine it can all be legit data.

You might try just stopping the dhcpd service and removing that file then restarting it.

Steve

Gertjan

@gabric098
During high-season I've seen some 100 clients connection to 'my' pfSense every day.
Some 40 company devices, 60 or so from clients on another LAN : a captive portal.

-rw-r--r--  1 dhcpd  _dhcp  78167 Feb 22 09:57 dhcpd.leases
-rw-r--r--  1 dhcpd  _dhcp  79183 Feb 22 09:08 dhcpd.leases~

these "1592644918" numbers tell me that the DHCPD is trying to re manage the leases file, but it was interrupted while doing so.
Keep in mind : it's not only the number of DHCP client that determine the load. There can be devices that ask for a new lease every xx seconds or so (yes, these exists and should be banned from any network). That device will stress the DHCPD server and not let him doing what it should be doing.

Also, and this is completely IMHO : I wouldn't try to 'drive' a 100+ network with a "1100", depending your using packages that can stress the device.

gabric098

Hi @gertjan ,
thanks for your reply.
Please note that 80% of the time the network has a lot less clients than 100. I was trying to consider the most extreme situation that rarely happens. It's a home network with 2 families connected and a bunch of IOT devices.
I do also suspect something goes wrong when dhcpd tries to "rotate" the dhcpd.leases file.
I can definitely try to delete the file and restart the service but I'd like to understand what's going wrong to address the root cause of the problem.
What log file shall I look at for dhcpd logs?

Thanks,
Gab

Gertjan

@gabric098 said in sg-1100 DHCP lease status page load time:

What log file shall I look at for dhcpd logs?

Dono if the dhcpd has option to tell you what it's doing.
I advise you to :
Ditch de leases file.
Get rid of the "ridiculous" /16

A typical lease record, like :

lease 192.168.2.80 {
  starts 6 2021/01/16 08:06:31;
  ends 6 2021/01/16 14:06:31;
  tstp 6 2021/01/16 14:06:31;
  cltt 6 2021/01/16 08:06:31;
  binding state free;
  hardware ethernet ec:c4:0d:xx:e4:89;
}

is 200 bytes in size.

When they all get used, over you 3 networks of /16 or 65535 max entries per networks make 3 x 65535 * 200 = 39 Mbytes (worst case). You are half way, and the 1100 is already struggling.
Make your networks more classic, like /24, and the problem will auto solve.
Btw : dono if the actual pool size might influence all this.

gabric098

I've cleaned up the /var/dhcpd/var/db directory and manually rotated the leases file. Essentially I've renamed the dhcpd.leasesto dhcpd.leases~ and created an empty dhcpd.leases file.
Now the GUI loads in no time. I'll keep monitoring the directory as I believe something fails during what is described in the man page:

In order to prevent the lease database from growing without bound, the file is rewritten from time to time. First, a temporary lease database is created and all known leases are dumped to it. Then, the old lease database is renamed /var/lib/dhcpd/dhcpd.leases~. Finally, the newly written lease database is moved into place.

Thanks,
Gab

stephenw10

Ah, yes what was the scope size? If it was close to the full /16 and you have a lot of new devices I could imagine that file becoming huge.

Steve

gabric098

@stephenw10
I'm not sure what you mean with scope size but I believe to understand that the problem here is not the number of active leases but rather the fact that in that files there were loads of very old leases like the one I posted which was from may 2020 (expired in the same day).

gabric098

Ok, this is weird.
As I mentioned before I had created an empty dhcp.leases file this morning creating a "backup" version dhcp.leases~.
After few hours I find again the 21MB dhcp.leases files with the first entry:

lease 10.40.44.246 {
  starts 2 2020/04/14 20:42:23;
  ends 2 2020/04/14 20:52:50;
  tstp 2 2020/04/14 20:52:50;
  cltt 2 2020/04/14 20:42:23;
  binding state free;
  hardware ethernet 2c:56:dc:b7:b7:57;
  uid "\001,V\334\267\267W";
}

... april 2020 ?

Gertjan

I've a theory : a zero byte dhcpd.leases file isn't .. valid.
So it took the backup - it recognized it as valid, and rebuild a good, huge dhcpd.leases.

Rename your backup to anything except dhcp.leases~ ( name it back.old.do-not-touch)
Jtst delete dhcpd.leases, as dhcpd will create it anyway.

stephenw10

By scope size I mean what is the range?

You have /16 subnets there but I assumed you didn't a DHCP range with 65534 possible leases.
If you have a large number of new devices they will just keep claiming new leases without overwriting to old ones > massive file!

Steve

pete35

@gabric098

is it possible for you to change the scopes to
10.20.0.0/21 / 10.30.0.0/21 / 10.40.0.0/21 ?
This will give more than 2000 addresses per scope, should be enough for your system und the leases db will not grow that much anymore.

gabric098

I see what you mean @stephenw10 and @pete35 .
I've just reduced the DHCP range from 10.x.5.1 to 10.x.15.255 for all the VLANs. That will give me plenty of addresses without bloating the file.
The dhcpd.leases file immediately reduced its size to a more manageable 900KB, I'll keep monitoring it in the next days to see if it stays the same or keeps growing.
I'll update the thread.

Thank you all for your precious support.
Gab