Illegal division by zero in bgwriter

[TheDromundKaas]

Hello,

I am using check_pgactivity via MRPE for my CheckMK installation.

For issue #373 I installed the new version of check_pgactivity to multiple hosts to check if it works. And while it works and I notified that it works for me, the bgwriter check on one of the hosts showed a strange unreliability.

Sometimes CheckMK complained that it got the return code 25 and an UNKNOWN state for the check. I tried to replicate the problem, but whenever I called the bgwriter service it went well.

I had almost given up and attributed the problem to some strange network connectivity, I set up a watch command with the bgwriter service and an echo of $?. And for a brief moment (2 seconds) I could see that the service returned

Illegal division by zero at /etc/check_mk/mrpe/check_pgactivity line 3060

The used command line was:

/etc/check_mk/mrpe/check_pgactivity --service bgwriter -U dbamon

Versions:

PostgreSQL 15.14
check_pgactivity 2.7
Perl 5.26.1

[frost242]

Hello,

Could you provide the content of line 3060 of check_pgactivity, as you were testing a development release. There's no division on this line but an instruction to populate a hash from the query result set.

[TheDromundKaas]

The line is from sub check_bgwriter:

$delta_buff_backend = ($rs[5] - $bgw{'buff_backend'}) / delta_ts;

[frost242]

Ah, thank you. Now I see.

On top of this line, there's $delta_ts = $now - $bgw{'ts'};
So it seems that check_pgactivity was called two times in the same second. So we have to do something to avoid this situation.

See https://perldoc.perl.org/functions/time

I hope I can manage to fix this tomorrow.

[TheDromundKaas]

I can add that the same thing happened today in Temp Files:

Illegal division by zero at /etc/check_mk/mrpe/check_pgactivity line 8745.

Line is 8745:

$frate = 60 * $diff_number / ($now - $last_check);

I saw the problem in my CheckMK instance and reproduced it by calling

/etc/check_mk/mrpe/check_pgactivity --service temp_files -U dbamon

on the command line. 10 successful executions, the 11th brought the error message.

Should I open a new issue, as this happens on a different service?

[frost242]

No, don't bother opening a new issue. Thanks for the report.

But you may execute your checks too frequently, as this problem occurs if the check is run within the same second as the previous check.

[TheDromundKaas]

I'll go check that out. The service checks in the GUI says it checks every 60 seconds. I am setting it to every 180 seconds. So that's all services check_pgactivity offers every 60 seconds.

But I guess that because the same script is used for all the checks that might expedite the problem, or rather create it.

[frost242]

That's strange. It should not happen then.
The only way I found to reproduce the issue is to run a second check immediately after the first :

$ ./check_pgactivity -F human -s bgwriter && ./check_pgactivity -F human -s bgwriter
Service        : POSTGRES_BGWRITER
Returns        : 0 (OK)
Message        : No writes
Perfdata       : buffers_backend=0Bps
Perfdata       : checkpoint_timed=0Nps
Perfdata       : checkpoint_req=0Nps
Perfdata       : buffers_checkpoint=0Bps
Perfdata       : buffers_clean=0Bps
Perfdata       : maxwritten_clean=0Nps
Perfdata       : buffers_backend_fsync=0Nps
Perfdata       : buffers_alloc=0Bps
Illegal division by zero at ./check_pgactivity line 3093.

[frost242]

Please, see commit e8cee24 in branch issue_388. This fixes the issue for bgwriter. A few services may be affected.

Now it's OK :
$ ./check_pgactivity -F human -s bgwriter && ./check_pgactivity -F human -s bgwriter
Service : POSTGRES_BGWRITER
Returns : 0 (OK)
Message : No writes
Perfdata : buffers_backend=0Bps
Perfdata : checkpoint_timed=0Nps
Perfdata : checkpoint_req=0Nps
Perfdata : buffers_checkpoint=0Bps
Perfdata : buffers_clean=0Bps
Perfdata : maxwritten_clean=0Nps
Perfdata : buffers_backend_fsync=0Nps
Perfdata : buffers_alloc=69.0337078651685Bps
Service : POSTGRES_BGWRITER
Returns : 0 (OK)
Message : No writes
Perfdata : buffers_backend=696705024Bps
Perfdata : checkpoint_timed=2706Nps
Perfdata : checkpoint_req=6Nps
Perfdata : buffers_checkpoint=2911166464Bps
Perfdata : buffers_clean=19267584Bps
Perfdata : maxwritten_clean=20Nps
Perfdata : buffers_backend_fsync=0Nps
Perfdata : buffers_alloc=13760241664Bps

[frost242]

Could it be that you have two daemons running at the same time ?

[frost242]

Commit 9dbef71 in the same branch provides a better fix for this issue. It uses gettimeofday instead of time(). Thus, all timed statistics are now calculated in a nanosecond range.