pfSense

Tested:

2.6.0-BETA (amd64)
built on Sun Jan 09 06:19:32 UTC 2022
FreeBSD 12.3-STABLE

This is being discussed here

https://forum.netgate.com/topic/168895/please-help-firewall-logs-dashboard-widget-not-updating

From a quick test, seems to work with 5 seconds, but set to 3 seconds and yeah seems to stall.

The problem is clear to me. If the widget processing time > than the refresh time the widget will be re triggered before the screen could be updated. The widget is extremely slow due to design errors.

An obvious one is the fact that it is reading and probably has to read the whole error log due to the possible selection criteria lets take two scenarios:
1) the positive one: The selection is ALL in combination with blocked. Lets assume that the probability of a block in an given firewallog is 1:5 and the requested number of messages is 20. In that case processing of 150 log entry's is almost certain enough
2) the bad one: I select one out of 15 interfaces and I select an interface with hardly any or no traffic ...... you have to read the multi thousand line firewallog and will perhaps even then not 20 lines matching the scenario

Apart from this principle issue, my feeling is that some code speedup is also possible

I did add debug time traces in the widget and it turned out that the html part of the code is causing the terrible delays. Below my time trace.

Further note that:
- someone all-ready limited the number of log lines analyzed by conv_log_filter to 50, which is IMHO low, where I surely agree that there must be an not too high limit
- during processing of the widget the processor load on my relatively powerful FW is raising from 1 to 25%
- the widget refresh time was set on 15 seconds, the time trace shows that the reality is often significant 'lower' (20 seconds is no exception)

However despite some mixed feeling about the php logline selection criteria, it is clear that that is not the bottleneck see the time trace below. Given the fact that the html code directly related to this widget is simple, my feeling is that the real problem is ^{higher up} in the dashboard / widget control code.

20221120_16:29:14_^START^
20221120_16:29:14_After request widgetkey
20221120_16:29:14_After nentries
20221120_16:29:14_After fetch iface_descr_arr
20221120_16:29:14_After filter array definition
20221120_16:29:14_After filling_filter array
20221120_16:29:14_After entries_interval
20221120_16:29:15_After ^{conv_log_filter}
20221120_16:29:15_After widgetkey_nodash
20221120_16:29:15_Before foreeach
20221120_16:29:15_Before HTML
20221120_16:29:16_Before HTML
20221120_16:29:17_Before HTML
20221120_16:29:18_Before HTML
20221120_16:29:18_Before HTML
20221120_16:29:19_Before HTML
20221120_16:29:20_Before HTML
20221120_16:29:21_Before HTML
20221120_16:29:21_Before HTML
20221120_16:29:22_Before HTML
20221120_16:29:23_Before HTML
20221120_16:29:24_Before HTML
20221120_16:29:25_Before HTML
20221120_16:29:25_Before HTML
20221120_16:29:26_Before HTML
20221120_16:29:27_Before HTML
20221120_16:29:28_Before HTML
20221120_16:29:28_Before HTML
20221120_16:29:29_Before HTML
20221120_16:29:30_Before HTML
20221120_16:29:30_After foreeach

I did some further analyses, and my previous conclusion was not correct. After making further changes and debugging the conclusion is that the line "$rule = find_rule_by_number($filterent['rulenum'], $filterent['tracker'], $filterent['act']); is causing the problem.

The good news is that with the actual functionality, that line is .... not necessary. The Bad new is that I would love to add the rule description in each second line.

What ever for now I fixed it by simply adding "//" in front of the rule line.

Below the time trace with the rule line active

Analysing firewalllog widget
20221120_19:55:38_^START^
20221120_19:55:38_After request widgetkey
20221120_19:55:38_After nentries
20221120_19:55:38_After fetch iface_descr_arr
20221120_19:55:38_After filter array definition
20221120_19:55:38_After filling_filter array
20221120_19:55:38_After entries_interval
20221120_19:55:38_After ^{conv_log_filter}
20221120_19:55:38_After widgetkey_nodash
20221120_19:55:38_Before foreeach
20221120_19:55:38_Rule lookup did take: 0.778216
20221120_19:55:39_Rule lookup did take: 0.770049
20221120_19:55:40_Rule lookup did take: 0.769228
20221120_19:55:41_Rule lookup did take: 0.769178
20221120_19:55:41_Rule lookup did take: 0.767633
20221120_19:55:42_Rule lookup did take: 0.771554
20221120_19:55:43_Rule lookup did take: 0.767103
20221120_19:55:44_Rule lookup did take: 0.769489
20221120_19:55:45_Rule lookup did take: 0.769441
20221120_19:55:45_Rule lookup did take: 0.769457
20221120_19:55:46_Rule lookup did take: 0.770208
20221120_19:55:47_Rule lookup did take: 0.770610
20221120_19:55:48_Rule lookup did take: 0.769436
20221120_19:55:48_Rule lookup did take: 0.770733
20221120_19:55:49_Rule lookup did take: 0.771599
20221120_19:55:50_Rule lookup did take: 0.770606
20221120_19:55:51_Rule lookup did take: 0.769298
20221120_19:55:52_Rule lookup did take: 0.766164
20221120_19:55:52_Rule lookup did take: 0.768438
20221120_19:55:53_Rule lookup did take: 0.770516
20221120_19:55:53_Before HTML
20221120_19:55:53_After HTML foreeach

The rule lookup function I disable to speedup the widget, was in opposite to my expectation in use to show the rule in case you hoover above the ^Act-field. That is surely useful functionality, however only possible in case of a very significant(!) performance increase of the ^{find_rule_by_number} function!

Note that at this moment the ^Act-field is based on the rule-lookup but that is not necessary. The act-field is also known without that lookup.

I will have a look at the ^{find_rule_by_number}, but fixing that one, is probably more something for NetGate