Notification slow on Solaris - 27+ seconds spent in "set_all_macro_environment_vars(TRUE); "?

[Steffen Poulsen]

Re: Notification slow on Solaris - 27+ seconds spent in "set_all_macro_environment_vars(TRUE);"?

Following up on previous debug, in rc1 we have inserted a few more debug statements in base/utils.c:

> log_debug_info(DEBUGL_FUNCTIONS,0,"setting env variables ...\n");

                /* set environment variables */
                set_all_macro_environment_vars(TRUE);

> log_debug_info(DEBUGL_FUNCTIONS,0,"closing command file ...\n");

And we got this:

[1200325554.988586] [001.0] [pid=11086] setting env variables ...
[1200325555.111295] [001.0] [pid=11086] process_macros()
[1200325555.111602] [001.0] [pid=11086] process_macros()
[1200325555.111661] [2048.1] [pid=11086] **** BEGIN MACRO PROCESSING ***********
[1200325555.111702] [2048.1] [pid=11086] Processing: 'xxx...'
[1200325555.111753] [2048.1] [pid=11086]   Done.  Final output: 'xxx...'
[1200325555.111800] [2048.1] [pid=11086] **** END MACRO PROCESSING *************
[1200325555.112067] [001.0] [pid=11086] process_macros()
[1200325555.112192] [001.0] [pid=11086] process_macros()
[1200325555.112301] [001.0] [pid=11086] process_macros()
[1200325555.112410] [001.0] [pid=11086] process_macros()
[1200325555.119389] [001.0] [pid=11086] process_macros()
[1200325555.119520] [001.0] [pid=11086] process_macros()
[1200325555.119629] [001.0] [pid=11086] process_macros()
[1200325555.119737] [001.0] [pid=11086] process_macros()
[1200325555.119847] [001.0] [pid=11086] process_macros()
[1200325555.119956] [001.0] [pid=11086] process_macros()
[1200325582.539891] [001.0] [pid=11086] closing command file ...

What can we do to lower this pretty large amount of time spend on setting the macro evn vars?

We're already running with use_large_installation_tweaks=1, but perhaps there are other helpful options touching the logic going on in set_all_macro_environment_vars?

We're at 3.0rc1, Solaris/SPARC, T1000.

Best regards,
Steffen Poulsen


-----Original Message-----
From: nagios-users-bounces at lists.sourceforge.net on behalf of Steffen Poulsen
Sent: Mon 14-01-2008 10:57
To: Nagios Users Mailinglist
Subject: Re: [Nagios-users] Notification slow on Solaris? / Debug: Executiontime=27.553 sec?
 
> There is no problems involved in running the plugins / 
> notifications at the command line, they execute in no time.
> 
> The delay we can see is from nagios stating in the nagios.log 
> that is going to send the alert and to the bash script / 
> check is actually executed.
> 
> So the delay probably has to do with the way nagios spawns 
> serialized commands (as we see it?).

Exerpt from debug log with (-1 / all):

[1200304088.239603] [001.0] [pid=4899] my_system()
[1200304088.239642] [256.1] [pid=4899] Running command '/usr/bin/printf
"%b" "***** Nagios *****\n\nNotification Type: RECOVERY\n\nService:
check_latency\nHost: xxx.xxx.dk\nAddress: 87.48.144.101\nState:
OK\n\nDate/Time: Mon Jan 14 10:48:08 MET 2008\n\nAdditional Info:\n\nOK
- Service Latency: 0.23 sec" | /usr/bin/mailx -s "** RECOVERY Service
Alert: nagsrv000.tele.dk/check_latency is OK **" xxx at xxx.dk'
...
[1200304088.239793] [064.1] [pid=4899] Making callbacks (type 10)...
[1200304088.320955] [001.0] [pid=5960] process_macros()
[1200304088.321398] [001.0] [pid=5960] process_macros()
[1200304088.321449] [2048.1] [pid=5960] **** BEGIN MACRO PROCESSING
***********
[1200304088.321486] [2048.1] [pid=5960] Processing: 'xxxx...'
[1200304088.321683] [2048.1] [pid=5960]   Done.  Final output: 'xxxx...'
[1200304088.321732] [2048.1] [pid=5960] **** END MACRO PROCESSING
*************
[1200304088.321824] [001.0] [pid=5960] process_macros()
[1200304088.321918] [001.0] [pid=5960] process_macros()
[1200304088.322010] [001.0] [pid=5960] process_macros()
[1200304088.322101] [001.0] [pid=5960] process_macros()
[1200304088.329595] [001.0] [pid=5960] process_macros()
[1200304088.329713] [001.0] [pid=5960] process_macros()
[1200304088.329821] [001.0] [pid=5960] process_macros()
[1200304088.329927] [001.0] [pid=5960] process_macros()
[1200304088.330035] [001.0] [pid=5960] process_macros()
[1200304088.330143] [001.0] [pid=5960] process_macros()
[1200304115.792892] [256.1] [pid=4899] Execution time=27.553 sec

The script appears to be called at the very late end of the "execution
time" stated, the script itself is executed in (much) less than 1 sec at
the command line.

Still: Solaris/SPARC, T1000, no noticable load (~1).

// Steffen Poulsen

-------------------------------------------------------------------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://ad.doubleclick.net/clk;164216239;13503038;w?http://sf.net/marketplace
_______________________________________________
Nagios-users mailing list
Nagios-users at lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nagios-users
::: Please include Nagios version, plugin version (-v) and OS when reporting any issue. 
::: Messages without supporting info will risk being sent to /dev/null



-------------------------------------------------------------------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://ad.doubleclick.net/clk;164216239;13503038;w?http://sf.net/marketplace
_______________________________________________
Nagios-users mailing list
Nagios-users at lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/nagios-users
::: Please include Nagios version, plugin version (-v) and OS when reporting any issue. 
::: Messages without supporting info will risk being sent to /dev/null