pfSense GUI damn(!) slow due to ^Firewall Logs^ widget
-
Looking at the logs via the status menu behaves normal. It is just the dashboard which is so damn slow.
That is relevant when
- login
- and when returning form whatever menu towards the dashboard.
I think that a better action then testing would be exterminating the widget code and perhaps (if necessary) adding a couple of time measurement debug statements.
If I can find the code related to the widget on github, I intent to have a look at the code myself as well
-
@louis2 said in pfSense GUI damn(!) slow due to ^Firewall Logs^ widget:
If I can find the code related to the widget on github,
No need to go that far.
/usr/local/www/widgets/widgets/log.widget.phpor here : https://github.com/pfsense/pfsense/blob/master/src/usr/local/www/widgets/widgets/log.widget.php
Looks the same to me.
@louis2 said in pfSense GUI damn(!) slow due to ^Firewall Logs^ widget:
and perhaps (if necessary) adding a couple of time measurement debug statements
The interesting part, I guess, is :
from line 80 to 101.
There are a couple of assignments and a function called conv_log_filter().
Add a log line with a time stamp : you will know quickly what function or place in the code eats up all the time.
Then, go to that function, and repeat adding log lines with time stamps.Afterwards, you'll find the classic foreach part that constructs the page.
-
Gertjan could you place the link to the code?
Other point is that I would like to see the rule name in the widget. Perhaps as a second line under IF
Sorry you did already provide some links
-
I am not a php or java expert, and I only reviewed the first part of the code but some remarks below.
First and most important one is that 'conv_log_filter' is fed with the total $filter_logfile = "{$g['varlog_path']}/filter.log"
Which does not seem clever to meI would only insert lets say max the last 100 lines of the filter log into the conv_log_filter ....
As said I did not look through all code and I am not a java, ajax or php expert, but here some things I was thinking waling through the first part of the code
Initial thoughts (note I am not an expert in gui programming)
if (is_numeric($_POST['filterlogentries'])) {
I would have expected an default value in case not numeric
I would also have expected a max value
$acts = array();
is an array containing the the choosen filter, but why is it an array since it contains only one valueThe widget key seems upperlevel to me, I do not understand why there is an an relation with a setting like != "All")
I understand there is a relation in regard to update frequency$filter_logfile = "{$g['varlog_path']}/filter.log";
that is clear it only looks into the actual (not compressed) log$filterlog = conv_log_filter($filter_logfile, $nentries, 50, $filterfieldsarray);
I wonder for which reason the 50 is there (50 lines max?), if so I think the max should be about 5 times the requested number of entrys since at this point you do not know the type of the fetched lines -
@louis2 said in pfSense GUI damn(!) slow due to ^Firewall Logs^ widget:
First and most important one is that 'conv_log_filter' is fed with the total $filter_logfile = "{$g['varlog_path']}/filter.log"
Which does not seem clever to meNoop.
$filter_logfile contains the path and file name of the log file.
/var:log/filter.log in this case.Then the conv_log_filter() set up a boat load of parser items, and calls finally :
/bin/cat '/var/log/filter.log.0' '/var/log/filter.log' | /usr/bin/tail -r -n 10000(I'm not bzipping my logs so this is a basic command line tail command)
It executes very fast.Then the resultant is filtered, and sorted if needed.
It took about half a second for my filter.log (864 Kbytes) and filter.log.0 (1069 Kbytes) to get the first 10000 lines, filter and sort, and show up the result - the widget.
As far as I can see, I found no DNS or other time consuming requests are needed
I'm using a Netgate 4100 on 22.05 btw (pfSense Plus), not the neck and code breaking 2.7.0. dev ;)
-
I simply do not know, I have to dig deeper. I had a short look at the filter.log, which seems a deep down pf log.
So it is clear that a couple of lookups are needed to convert the output to what is represented on the GUI.
I not even find source and destination in that file so that has to be correlated as well.
So it is not simply select a few records and show them in the widget.
The processing is of cause all most identical as the one used when showing the firewall log under system logs. I Had expect ^a logfiles on an higher level^
Whats ever I have to dig deeper and it would help if I could edit the code, compile it install and remove it with pkg for testing changes.
-
@louis2 The most time consuming / performance hungy widget in our experience are firewall logs (that don't make sense for me on a dashboard as theres less info then necessary for me to look at) and the traffic graphs. Removing those widgets were always a huge performance boost and all nagging about "pfsense / the firewall being super slow" vanished instantly.
So would be interesting in your case to remove them both and check the speed of the dashboard again?
Cheers
-
Since I am investigating, I am sitting behind the pc, and did test it instantly.
But it is not true, it is really the firewall log widget ! Removing the traffic graphs has no or little impact
-
I am analyzing the widget. From what I think to know now.
Layout ^filter.log^
<134>1
2022-11-17 # date
T11:03:43.334983+01:00 # time
pfSense.lan # # pfsense domain
filterlog 72303 - - # ?
963, # ?
, # ?
, # ?
1558685482, # ?
lagg1.18, # vlan
match, # mached a rule
block, # result = block
in, # ?
4, # ?
0x0, # ?
, # ?
1, # ?
62353, # ?
0, # ?
none, # ?
103, # ?
pim, # protocol ?
46, # ?
192.168.18.1, # source
224.0.0.13, # destination
datalength=26 # package lengthColumns shown in widget
Act Time IF Source Destination$user_settings # the user defined settings
$nentries # seems to define the filter based on user settings
$iface_descr_arr # used to convert technical interface name to ^IF^
$filterfieldsarray # ?? During filling of the the array interface technical names are converted to interface names using the $filterfieldsarray
$filterlog # ??? Filerlog is filled using >>conv_log_filter<< which is using the $filter_logfile and $filterfieldsarray and also the user defined $nentries
$filterent # Seems to be an element of $filterlog
$filterent # Seems to be an array as well haveing the following fields: 'rulenum' 'tracker' 'act' 'time' 'interface' 'srcIP' 'dstIP' 'dstport'
There seems to be an option for an reverse DNS-lookupAmong other things for better understanding:
- need the definition of the logfile
- need the code / of "conv_log_filter"
ANd it would be nice to have a function to lookup the firewall rule attributes among them "description" ion order to add that to the widget layout !!!
-
@louis2 said in pfSense GUI damn(!) slow due to ^Firewall Logs^ widget:
But it is not true, it is really the firewall log widget ! Removing the traffic graphs has no or little impact
Interesting. In a few cases that really had more impact than the firewall one, but good to know. Personally I don't see much use for the firewall widget but it shouldn't slow the dash down so much, sure.
Nevertheless we never got much use out of that small widget concerning rulesets as either there's too much to display (too many pps that are displayed for it to make sense) or if there IS an interesting hit, it can go away too quickly or doesn't display the information needed. So I have to hop to the firewall log screen anyway. -
If I log into the FW for some reason, to add or change something, I am not always going to check the logs.
However the first thing I do after a login, is look at e.g. that Firewall widget to see if there is something strange.
For a deeper investigation, I use the logs and or perhaps even more often wireshark
-
@louis2 said in pfSense GUI damn(!) slow due to ^Firewall Logs^ widget:
However the first thing I do after a login, is look at e.g. that Firewall widget to see if there is something strange.
Just curious: How long is your widget to display? I have a great number of customers where that wouldn't do anything to help me see "anything strange" as the default blocking on WAN is simply too much noise and disabling it you don't see the stuff that hits you anymore. But in bigger setups those logs are shipped off the firewall to log/monitoring systems (like graylog etc.) to correlate with other systems anyway.
-
I defined 20 entrys refresh 15 seconds. It just give a first impression. But IHMO not unimportant.
For private use you normally do not have a syslog/greylog server. The local log is mostly enough.
However since 2.7 or at least since that time frame, my IPV6 gateway widget turns red. After some investigation I know, that despite the "interface being red" it is working
For that reason I installed an greylog instance on my NAS, but up to now I could not find a course. In fact I stopped my investigation effort hoping that the problem would be gone with the introduction of FreeBSD 14-current. However the issue is still there
-
Do you see the same delay when the widget refreshes?
Or rather you've set the update to 15s but it creates a similar length delay when you load the page. Does it result in a 30s refresh?
Steve
-
If I am on looking at the Dashboard page, I do not notice any strange thing. The traffic graphs are very nicely constantly updated etc, without any falter.
If I change the refresh interval e.g. to two seconds, the behavoir does not change
-
Hmm, and the firewall logs widget does update?
If so that implies it only affects the initial load and not the update, which must parse the same data.
-
The fact that I do not see any thing special in regard to the dashboard behavoir, does not say much.
The only thing you can conclude is that the dashboard page is waiting for the widget before it opens.
At the moment the dashboard is there, it is not so easy to say how long it takes the more or less static widget to refresh itself. The more because I did set the refresh time to 15 seconds which is not far apart from the about 16 seconds it takes for the widget to refresh itself
-
Try adding a block rule with logging for something you can generate, a local ping for example. Then you should see that with new hits each time it updates.
That seems pretty key to understanding where the delay is if it can refresh the data there without an issue.
What sort of timing values do you see if you open the dash in a browser profiler?
On a 6100 I see log widget takes almost exactly 2.2s each refresh. That seems slow to me but is much faster than 16s. And it's exactly the same the first time it loads after I refresh the page. -
Nop I did some tests:
- When I try to go to the widgets settings menu, I have immediate
reaction - when putting save it takes ... long
- when I set the refresh time to two seconds and generate alarm, then do not occur any longer !!
We are trying to analyze the problem by looking from the outside. If I could create a package containing the widget code and those of the functions it calls, then I could modify the code and test where it goes wrong and trying to improve that.
I / we need some means to test the equivalent of the widget without having to compile pfSense as a whole
- When I try to go to the widgets settings menu, I have immediate
-
Hmm, failing to update below 5s was a known issue. That should be fixed but I wonder if there has been a regression: https://redmine.pfsense.org/issues/12673
You should add a note there if it fails to update again.Steve
