[solved] Occasional Gaps in Graph

[willieb]

Operating System: Windows Server 2003 R2 Standard x64 SP2
Server: Dual Processor Dual Core E5520 Xeon, 8GB RAM
Webserver: IIS 6
Cacti: 0.8.7g
Spine: 0.8.7g
MySQL: 5.1.57 (32 Bit)
PHP: 5.3.3
RRDTool: 1.2.15-cygwin-1.5.20
Net-SNMP: 5.5.0.2
Plugin Architecture: 2.9
1 Minute Polling, 1 Minute Scheduled Task

I about have everything with the install working, but I have an occasional gap in my graphs. I used to have many more gaps but to reduce the gaps I've changed several things. I went from 5 minute task to 1 minute task. This reduced the gaps to less than 5 minutes. I also removed boost & changed from spine to cmd.php and 1 process, 1 thread. And I increased memory_limit in php.ini from 128M to 1G. Since I've only had one 3 minute gap since the last 24 hours. Here's my cacti logs and event in windows. I assume this is mysql/memory related but not sure what to try to fix it, maybe you guys can help.

The gap was for 3 minutes from 1:15am to 1:17am. It recovered at 1:18am. I have logs from 1:15am then it skips to 1:18am. See below:

1:15am

Code: Select all

07/07/2011 01:15:09 AM - WEATHERMAP: Poller[0] STATS: Weathermap 0.97a run complete - Thu, 07 Jul 11 01:15:09 -0400: 1 maps were run in 2 seconds with 0 warnings.
07/07/2011 01:15:09 AM - WEATHERMAP: Poller[0] [Map 7] ATC Ring.conf: Wrote map to D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.png and D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.thumb.png
07/07/2011 01:15:08 AM - WEATHERMAP: Poller[0] [Map 7] ATC Ring.conf: About to write image file. If this is the last message in your log, increase memory_limit in php.ini [WMPOLL01]
07/07/2011 01:15:07 AM - WEATHERMAP: Poller[0] [Map 7] ATC Ring.conf: Map: D:\Inetpub\cacti.accessatc.net\plugins\weathermap\configs\ATC Ring.conf -> D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.html & D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.png
07/07/2011 01:15:07 AM - WEATHERMAP: Poller[0] Weathermap 0.97a starting - Normal logging mode. Turn on DEBUG in Cacti for more information
07/07/2011 01:15:07 AM - SYSTEM THOLD STATS: Time:0.3358 Tholds:65 Hosts:0
07/07/2011 01:15:07 AM - SYSTEM STATS: Time:6.1588 Method:cmd.php Processes:1 Threads:N/A Hosts:22 HostsPerProcess:22 DataSources:602 RRDsProcessed:311 

Nothing for 1:16am & 1:17am
Here's 1:18am

Code: Select all

07/07/2011 01:18:09 AM - WEATHERMAP: Poller[0] STATS: Weathermap 0.97a run complete - Thu, 07 Jul 11 01:18:09 -0400: 1 maps were run in 1 seconds with 0 warnings.
07/07/2011 01:18:09 AM - WEATHERMAP: Poller[0] [Map 7] ATC Ring.conf: Wrote map to D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.png and D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.thumb.png
07/07/2011 01:18:09 AM - WEATHERMAP: Poller[0] [Map 7] ATC Ring.conf: About to write image file. If this is the last message in your log, increase memory_limit in php.ini [WMPOLL01]
07/07/2011 01:18:08 AM - WEATHERMAP: Poller[0] [Map 7] ATC Ring.conf: Map: D:\Inetpub\cacti.accessatc.net\plugins\weathermap\configs\ATC Ring.conf -> D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.html & D:\Inetpub\cacti.accessatc.net\plugins\weathermap\output\bdcb4a3925ba195ecce6.png
07/07/2011 01:18:08 AM - WEATHERMAP: Poller[0] Weathermap 0.97a starting - Normal logging mode. Turn on DEBUG in Cacti for more information
07/07/2011 01:18:08 AM - SYSTEM THOLD STATS: Time:0.3302 Tholds:65 Hosts:0
07/07/2011 01:18:07 AM - SYSTEM STATS: Time:7.0571 Method:cmd.php Processes:1 Threads:N/A Hosts:22 HostsPerProcess:22 DataSources:602 RRDsProcessed:311
[b]07/07/2011 01:18:00 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 602, Data Sources: 5min_cpu(DS[8]), traffic_in(DS[9]), traffic_out(DS[9]), traffic_in(DS[10]), traffic_out(DS[10]), traffic_in(DS[11]), traffic_out(DS[11]), traffic_in(DS[12]), traffic_out(DS[12]), traffic_in(DS[13]), traffic_out(DS[13]), traffic_in(DS[14]), traffic_out(DS[14]), traffic_in(DS[15]), traffic_out(DS[15]), traffic_in(DS[16]), traffic_out(DS[16]), traffic_in(DS[17]), traffic_out(DS[17]), traffic_in(DS[18]), traffic_out(DS[18]), Additional Issues Remain. Only showing first 20[/b]
07/07/2011 01:18:00 AM - POLLER: Poller[0] WARNING: Scheduled Task is out of sync with the Poller Interval! The Poller Interval is '60' seconds, with a maximum of a '300' second Scheduled Task, but 120 seconds have passed since the last poll! 

I would expect the Scheduled Task out of sync error but I don't know what the "POLLER: Poller[0] WARNING:" error means.

I'm not sure if this has anything to do with the gap as I see several of the messages throughout the windows event viewer, it shows these in at 1:17am

Code: Select all

1:17:12am
Source: userenv
Windows cannot unload your classes registry file - it is still in use by other applications or services. The file will be unloaded when it is no longer in use.

1:17:12am
Source: userenv
Windows saved user ATCRAD2\Cacti registry while an application or service was still using the registry during log off. The memory used by the user's registry has not been freed. The registry will be unloaded when it is no longer in use. 

This is often caused by services running as a user account, try configuring the services to run in either the LocalService or NetworkService account.

1:17:23am
Source: userenv
Windows unloaded user S-1-5-21-1783885167-3162585954-3309554527-1015_Classes registry when it received a notification that no other applications or services were using the profile.

1:17:34
Source: MSSQL$RADB
A significant part of sql server process memory has been paged out. This may result in a performance degradation. Duration: 28851 seconds. Working set (KB): 16080, committed (KB): 91816, memory utilization: 17%%.

[gandalf]

In case this is a performance problem, I feel it is better to move this to the windows forum
R.

[willieb]

Ok thanks gandalf. The server is fairly stout, only running cacti & dependencies. I am graphing CPU and memory. CPU is less than 2% for each processor. Paging is a touch over 2GB.

But it still could be windows related I'm sure...

[willieb]

It did it again, 8:48, 8::49, & 8:50 was blank. Here's the 8:50 last line:

07/07/2011 08:49:59 PM - WEATHERMAP: Poller[0] [Map 7] ATC Ring.conf: About to write image file. If this is the last message in your log, increase memory_limit in php.ini [WMPOLL01]

But memory_limit is already set to 1G. Is that not enough? I don't really have that many graphs yet...

Or does that only pertain to weathermap? Could weathermap config be causing the gaps?

[BSOD2600]

1) when you switch to 1 min polling, did you follow the guides and convert your data sources, rrd files, etc? If not, this is a problem which needs to be corrected.

2) Are you having gaps in other graphs or just weather map? If the latter, then sounds more like a weathermap/plugin issue than your cacti system.

3) The various userenv events... have you considered installing microsoft uphclean? it helps with releasing handles, etc during user log offs for 'dirty' applications.

4) MSSQL$RADB this is Microsoft SQL, not MySQL. Did you look online on how to resolve this issue? For example: http://support.microsoft.com/kb/918483

[willieb]

1) when you switch to 1 min polling, did you follow the guides and convert your data sources, rrd files, etc? If not, this is a problem which needs to be corrected.

2) Are you having gaps in other graphs or just weather map? If the latter, then sounds more like a weathermap/plugin issue than your cacti system.

3) The various userenv events... have you considered installing microsoft uphclean? it helps with releasing handles, etc during user log offs for 'dirty' applications.

4) MSSQL$RADB this is Microsoft SQL, not MySQL. Did you look online on how to resolve this issue? For example: http://support.microsoft.com/kb/918483

1) Yes. I followed http://forums.cacti.net/viewtopic.php?f=6&t=23885. The last 2 posts to the thread was the steps I took. This was a fresh Cacti install so I simply deleted the rra files instead of trying to convert them.

2) gaps are in all graphs at the same time, even graphs from scripts such as localhost cpu and cacti poller graphs. This weekend I am going to disable weathermap and see if that helps. If I have no gaps for the whole weekend I'll know it's weathermap related. Plus without weathermap installed, if the problem still exists it will be easier to troubleshoot.

3) I didn't know about uphclean. I will look into that and consider it, or possibly changing the user for the scheduled task to "localservice" or similar.

4) I didn't even notice it was for MS SQL, lol. Good catch. MS SQL is installed for another application not in use.I am no longer concerned with this error.

Thanks for the reply and I'll post results after the weekend.

[willieb]

Ok I disabled weathermap but it's still happening.

There's a gap 2:23pm, 2:24pm. Here's the log:

07/09/2011 02:29:11 PM - SYSTEM THOLD STATS: Time:0.3750 Tholds:65 Hosts:0
07/09/2011 02:29:10 PM - SYSTEM STATS: Time:9.7333 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349
07/09/2011 02:28:22 PM - SYSTEM THOLD STATS: Time:0.3815 Tholds:65 Hosts:0
07/09/2011 02:28:22 PM - SYSTEM STATS: Time:11.0423 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349
07/09/2011 02:28:11 PM - POLLER: Poller[0] WARNING: Scheduled Task is out of sync with the Poller Interval! The Poller Interval is '60' seconds, with a maximum of a '300' second Scheduled Task, but 69 seconds have passed since the last poll!
07/09/2011 02:27:11 PM - SYSTEM THOLD STATS: Time:0.3042 Tholds:65 Hosts:0
07/09/2011 02:27:11 PM - SYSTEM STATS: Time:9.0764 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349
07/09/2011 02:26:10 PM - SYSTEM THOLD STATS: Time:0.3476 Tholds:65 Hosts:0
07/09/2011 02:26:10 PM - SYSTEM STATS: Time:9.1957 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349
07/09/2011 02:25:21 PM - SYSTEM THOLD STATS: Time:0.3139 Tholds:65 Hosts:0
07/09/2011 02:25:21 PM - SYSTEM STATS: Time:10.3046 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:356
07/09/2011 02:25:10 PM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 647, Data Sources: 5min_cpu(DS[8]), traffic_in(DS[9]), traffic_out(DS[9]), traffic_in(DS[10]), traffic_out(DS[10]), traffic_in(DS[11]), traffic_out(DS[11]), traffic_in(DS[12]), traffic_out(DS[12]), traffic_in(DS[13]), traffic_out(DS[13]), traffic_in(DS[14]), traffic_out(DS[14]), traffic_in(DS[15]), traffic_out(DS[15]), traffic_in(DS[16]), traffic_out(DS[16]), traffic_in(DS[17]), traffic_out(DS[17]), traffic_in(DS[18]), traffic_out(DS[18]), Additional Issues Remain. Only showing first 20
07/09/2011 02:25:10 PM - POLLER: Poller[0] WARNING: There are '1' detected as overrunning a polling process, please investigate
07/09/2011 02:25:10 PM - POLLER: Poller[0] WARNING: Scheduled Task is out of sync with the Poller Interval! The Poller Interval is '60' seconds, with a maximum of a '300' second Scheduled Task, but 70 seconds have passed since the last poll!
07/09/2011 02:24:59 PM - SYSTEM THOLD STATS: Time:0.0083 Tholds:0 Hosts:0
07/09/2011 02:24:59 PM - SYSTEM STATS: Time:58.0701 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:0
07/09/2011 02:24:59 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/09/2011 02:23:12 PM - SYSTEM THOLD STATS: Time:0.3008 Tholds:65 Hosts:0
07/09/2011 02:23:11 PM - SYSTEM STATS: Time:9.4143 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349
07/09/2011 02:22:11 PM - SYSTEM THOLD STATS: Time:0.3410 Tholds:65 Hosts:0
07/09/2011 02:22:10 PM - SYSTEM STATS: Time:9.7642 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349
07/09/2011 02:21:11 PM - SYSTEM THOLD STATS: Time:0.2671 Tholds:65 Hosts:0
07/09/2011 02:21:11 PM - SYSTEM STATS: Time:9.3127 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349
07/09/2011 02:20:11 PM - SYSTEM THOLD STATS: Time:0.2896 Tholds:65 Hosts:0
07/09/2011 02:20:10 PM - SYSTEM STATS: Time:9.7799 Method:cmd.php Processes:1 Threads:N/A Hosts:23 HostsPerProcess:23 DataSources:654 RRDsProcessed:349

[willieb]

Still happening after shutting down weathermap.

There was a gap at 4:54, 4:55, & 4:56. This is all that's for 4:55...

07/10/2011 04:55:02 PM - POLLER: Poller[0] NOTE: Poller Int: '60', Scheduled Task Int: '60', Time Since Last: '60', Max Runtime '58', Poller Runs: '1'
07/10/2011 04:55:02 PM - POLLER: Poller[0] DEBUG: About to Spawn a Remote Process [CMD: c:/php/php.exe, ARGS: -q "d:/inetpub/cacti.accessatc.net/cmd.php" 0 35]
07/10/2011 04:56:01 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.


There's 100's of lines for each poll in the log and don't really know what to look for. I'm going to try setting the task user as localservice user and see if that helps. If not I'll try uphclean and will post results. Thanks for any help or ideas you may have...

Edit: After a bit of googling I went ahead and installed uphclean. I'll give it a couple days and see if the gaps still appear.

[BSOD2600]

It's appearing that your poller is occasionally running longer than 60 seconds, which is then causing problems with the subsequent polling cycles. Have you tried switching to the spine poller yet? Its a lot more efficient (but also has its quirks). You'll also want to find out why the cmd.php poller is running longer than 60 seconds; typically this is due to a rouge script. Sysinternals process monitor will help find out what scripts(s) are being executed/waiting.

[willieb]

It's appearing that your poller is occasionally running longer than 60 seconds, which is then causing problems with the subsequent polling cycles. Have you tried switching to the spine poller yet? Its a lot more efficient (but also has its quirks). You'll also want to find out why the cmd.php poller is running longer than 60 seconds; typically this is due to a rouge script. Sysinternals process monitor will help find out what scripts(s) are being executed/waiting.

I started out with spine since I will potentially have more than 1000 graphs and 100+ devices with 1 minute polling. It actually ran faster but had more gaps in it than cmd. The reason I went to cmd with 1 process and 1 thread is that it was what settings I used on an old cacti install that had no gaps. It also was the default, and I was trying to rule out spine as the culprit.

Speaking of rouge scripts, the only script I'm running within the poll is for windows monitoring. I may disable that device as a step in troubleshooting but if I remember correctly it was happening before I added monitoring for localhost but I've changed a lot since then.

Since installing uphclean, so far no gaps since 4:54pm yesterday but I don't think it's been long enough to determine if it's fixed or not. If it happens again I will try Sysinternals and see what it tells me.

I really appreciate the reply/help BSOD2600. I'll keep the thread updated as things progress.

[willieb]

I am fairly convinced this was fixed with uphclean. Here's the download link: http://www.microsoft.com/download/en/de ... px?id=6676

Taking it slow, in another day or so I will re-enable weathermap & spine. Thanks for all the help and replies.

Cacti is truly one of my favorite network tools, thanks for all the hard development work!

[BSOD2600]

Glad it solved your issues. Windows vista/7/2008/R2 natively implement UPHClean.

[willieb]

I spoke to soon. Unfortunately it started back right after my last post in this thread. 3 days with no gaps I would have thought it would have been fixed.

I'll look at how to use Sysinternals process monitor and go from there. I don't know if I can capture the running processes or I'll have to watch it live. We'll see...

[BSOD2600]

The gap correspond with "Poller Output Table not Empty." or "Scheduled Task is out of sync with the Poller Interval" events in the cacti log per chance?

[willieb]

Yes. I guess I get the out of sync messages because every now and then the poller is running longer than 58 seconds. So the next run it detects it's been longer than the scheduled 60 seconds.

D:\Inetpub\cacti.accessatc.net\log>findstr /C:"58 seconds" cacti.old.log
07/11/2011 10:18:59 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/13/2011 06:33:59 AM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/13/2011 02:18:59 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/13/2011 06:52:03 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/14/2011 07:00:02 AM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/14/2011 07:10:03 AM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/14/2011 12:00:04 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/14/2011 05:11:59 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.
07/14/2011 10:05:59 PM - POLLER: Poller[0] Maximum runtime of 58 seconds exceeded. Exiting.

D:\Inetpub\cacti.accessatc.net\log>

Also see output files attached for the commands below:

D:\Inetpub\cacti.accessatc.net\log>findstr /C:"Output Table" cacti.log > cacti.grep.ot.txt

D:\Inetpub\cacti.accessatc.net\log>findstr /C:"out of sync" cacti.log > cacti.grep.oos.txt

Thanks.