Some Weathermaps not updating

[saguaro]

I just want to be clear and not confuse these 2 issues , but I am tracking a few issues. Below is from the old system and these are MAX maps that are taking too long to complete.

The other issue is on the new system, maps not updating but rrd data is current. That I will post in the next post.


Here is the output from the manual weathermap run on this single map - old system.

time /opt/lampp/bin/php /opt/lampp/htdocs/cacti/plugins/weathermap/./weathermap --no-data --config CoreMAX.conf --output temp.png

WARNING: CoreMAX.conf: Failed to load ttf font VeraBd - at config line 3/./weathermap --no-data --config CoreMAX.conf --output temp.png [WMWARN30]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN36]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN03]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN36]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN03]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
374 lines Laaaator of the above ---------------------------

real 0m0.664s
user 0m0.609s
sys 0m0.048s

As you said it is less than a second when simple test executed. But 214 seconds when poller executes it.... Strangeness

Only Summary lines
03/27/2017 09:45:53 AM - WEATHERMAP: Poller[0] Weathermap 0.97a starting - Normal logging mode. Turn on DEBUG in Cacti for more information
03/27/2017 09:49:27 AM - WEATHERMAP: Poller[0] WARNING: [Map 199] CoreMAX.conf: TIME: /opt/lampp/htdocs/cacti/plugins/weathermap/configs/CoreMAX.conf took 214 seconds.
03/27/2017 09:49:27 AM - WEATHERMAP: Poller[0] STATS: Weathermap 0.97a run complete - Mon, 27 Mar 17 09:49:27 -0400: 1 maps were run in 214 seconds with 1 warnings.

[saguaro]

New System - Issue with updated RRD data but PNG is old from March 16th
EPOCH TIME is current for rrd - GMT: Mon, 27 Mar 2017 13:35:05 GMT
Correct, I am in Eastern time.

ls -l | grep 386cffef2965c1f1825d
-rw-r--r-- 1 root root 22268 Mar 16 08:52 386cffef2965c1f1825d.html
-rw-r--r-- 1 root root 43330 Mar 16 08:52 386cffef2965c1f1825d.png
-rw-r--r-- 1 root root 34923 Mar 16 08:52 386cffef2965c1f1825d.thumb.png

ls -l | grep 14105.rrd
-rw-r--r-- 1 root root 94816 Mar 27 10:40 nodeXX_traffic_in_14105.rrd


rrdtool info /var/www/html/cacti/rra/nodeXX_net_traffic_in_14105.rrd

filename = "/var/www/html/cacti/rra/nodeXX_traffic_in_14105.rrd"
rrd_version = "0003"
step = 300
last_update = 1490621705
ds[traffic_in].type = "COUNTER"
ds[traffic_in].minimal_heartbeat = 600
ds[traffic_in].min = 0.0000000000e+00
ds[traffic_in].max = 2.0000000000e+10
ds[traffic_in].last_ds = "8015874236919927"
ds[traffic_in].value = 1.6545235513e+09
ds[traffic_in].unknown_sec = 0
ds[traffic_out].type = "COUNTER"
ds[traffic_out].minimal_heartbeat = 600
ds[traffic_out].min = 0.0000000000e+00
ds[traffic_out].max = 2.0000000000e+10
ds[traffic_out].last_ds = "6977288615052867"
ds[traffic_out].value = 1.3834119588e+09
ds[traffic_out].unknown_sec = 0
rra[0].cf = "AVERAGE"
rra[0].rows = 600
rra[0].cur_row = 553
rra[0].pdp_per_row = 1
rra[0].xff = 5.0000000000e-01
rra[0].cdp_prep[0].value = NaN
rra[0].cdp_prep[0].unknown_datapoints = 0
rra[0].cdp_prep[1].value = NaN
rra[0].cdp_prep[1].unknown_datapoints = 0
rra[1].cf = "AVERAGE"
rra[1].rows = 700
rra[1].cur_row = 472
rra[1].pdp_per_row = 6
rra[1].xff = 5.0000000000e-01
rra[1].cdp_prep[0].value = 3.3057552612e+08
rra[1].cdp_prep[0].unknown_datapoints = 0
rra[1].cdp_prep[1].value = 2.7652949685e+08
rra[1].cdp_prep[1].unknown_datapoints = 0
rra[2].cf = "AVERAGE"
rra[2].rows = 775
rra[2].cur_row = 573
rra[2].pdp_per_row = 24
rra[2].xff = 5.0000000000e-01
rra[2].cdp_prep[0].value = 6.3446030165e+09
rra[2].cdp_prep[0].unknown_datapoints = 0
rra[2].cdp_prep[1].value = 4.6805591581e+09
rra[2].cdp_prep[1].unknown_datapoints = 0
rra[3].cf = "AVERAGE"
rra[3].rows = 797
rra[3].cur_row = 569
rra[3].pdp_per_row = 288
rra[3].xff = 5.0000000000e-01
rra[3].cdp_prep[0].value = 5.2519040943e+10
rra[3].cdp_prep[0].unknown_datapoints = 0
rra[3].cdp_prep[1].value = 3.8333636400e+10
rra[3].cdp_prep[1].unknown_datapoints = 0
rra[4].cf = "MAX"
rra[4].rows = 600
rra[4].cur_row = 301
rra[4].pdp_per_row = 1
rra[4].xff = 5.0000000000e-01
rra[4].cdp_prep[0].value = NaN
rra[4].cdp_prep[0].unknown_datapoints = 0
rra[4].cdp_prep[1].value = NaN
rra[4].cdp_prep[1].unknown_datapoints = 0
rra[5].cf = "MAX"
rra[5].rows = 700
rra[5].cur_row = 462
rra[5].pdp_per_row = 6
rra[5].xff = 5.0000000000e-01
rra[5].cdp_prep[0].value = 3.3057552612e+08
rra[5].cdp_prep[0].unknown_datapoints = 0
rra[5].cdp_prep[1].value = 2.7652949685e+08
rra[5].cdp_prep[1].unknown_datapoints = 0
rra[6].cf = "MAX"
rra[6].rows = 775
rra[6].cur_row = 301
rra[6].pdp_per_row = 24
rra[6].xff = 5.0000000000e-01
rra[6].cdp_prep[0].value = 3.7949929543e+08
rra[6].cdp_prep[0].unknown_datapoints = 0
rra[6].cdp_prep[1].value = 2.7652949685e+08
rra[6].cdp_prep[1].unknown_datapoints = 0
rra[7].cf = "MAX"
rra[7].rows = 797
rra[7].cur_row = 462
rra[7].pdp_per_row = 288
rra[7].xff = 5.0000000000e-01
rra[7].cdp_prep[0].value = 5.9137446422e+08
rra[7].cdp_prep[0].unknown_datapoints = 0
rra[7].cdp_prep[1].value = 4.5053880163e+08
rra[7].cdp_prep[1].unknown_datapoints = 0

[saguaro]

New System - Issue with updated RRD data but PNG is old from March 16th

I can run this map manually, it grabs the current rrd data and updates the the current png. However Grepping the last logs yields no results of ever running that map at all. ?? I checked the conf file as we keep backups every day and there has been no changes to it at all.

time php ./weathermap --config /var/www/html/cacti/plugins/weathermap/configs/ORG.conf --output /var/www/html/cacti/plugins/weathermap/output/386cffef2965c1f1825d.png

real 0m0.506s
user 0m0.412s
sys 0m0.083s

[Howie]

New System - Issue with updated RRD data but PNG is old from March 16th

I can run this map manually, it grabs the current rrd data and updates the the current png. However Grepping the last logs yields no results of ever running that map at all. ?? I checked the conf file as we keep backups every day and there has been no changes to it at all.

time php ./weathermap --config /var/www/html/cacti/plugins/weathermap/configs/ORG.conf --output /var/www/html/cacti/plugins/weathermap/output/386cffef2965c1f1825d.png

real 0m0.506s
user 0m0.412s
sys 0m0.083s

This is correct behaviour. The command-line tool doesn't log to Cacti's logs. It's intended for non-Cacti users (e.g. MRTG, librenms). The CLI tool logs to the console only.

When it runs from the poller, there should definitely be some log entries for it though. Are there? I would guess not. So back to: what is the last logged line (it should be WEATHERMAP STATS)? What's special about this map or the one before it (if it's that one that kills the poller)?

[Howie]

I just want to be clear and not confuse these 2 issues , but I am tracking a few issues. Below is from the old system and these are MAX maps that are taking too long to complete.

The other issue is on the new system, maps not updating but rrd data is current. That I will post in the next post.


Here is the output from the manual weathermap run on this single map - old system.

time /opt/lampp/bin/php /opt/lampp/htdocs/cacti/plugins/weathermap/./weathermap --no-data --config CoreMAX.conf --output temp.png

WARNING: CoreMAX.conf: Failed to load ttf font VeraBd - at config line 3/./weathermap --no-data --config CoreMAX.conf --output temp.png [WMWARN30]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: ICON 'images/Router.png' does not exist, or is not readable. Check path and permissions. [WMARN38]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN36]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN03]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN36]
WARNING: CoreMAX.conf: Using a non-existent special font (10) - falling back to internal GD fonts [WMWARN03]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
WARNING: CoreMAX.conf: Angled text doesn't work with non-FreeType fonts [WMWARN02]
374 lines Laaaator of the above ---------------------------

real 0m0.664s
user 0m0.609s
sys 0m0.048s

So there are missing images, missing fonts... you aren't going to get the map you want anyway.

As you said it is less than a second when simple test executed. But 214 seconds when poller executes it.... Strangeness

But the difference is that it isn't fetching any data. So you know for sure that that's the issue and not something about processing the image itself.

In the cacti.log for a normal run of this map, do you get any ReadData warnings? That's the part where data is being fetched for the map.

[saguaro]

Ok so no log for the cli, but poller is running on the new system. I have a few old logs I can go through to find something. I do have a few old hung pollers out there. I will kill them and then start logging fresh again to try and catch when this happens. But like I said I think they are overlapping so not sure if I can catch a trigger. I am having another system built so we can move maps over to it. Maybe I will be able to isolate a few maps at a time without interrupting production.

ps -ef | grep poller
root 9492 9488 0 Mar24 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 9494 9492 0 Mar24 ? 00:05:00 /usr/bin/php /var/www/html/cacti/poller.php
root 13306 13305 0 Mar22 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 13307 13306 0 Mar22 ? 00:04:58 /usr/bin/php /var/www/html/cacti/poller.php
root 13760 13759 0 12:35 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 13761 13760 61 12:35 ? 00:04:07 /usr/bin/php /var/www/html/cacti/poller.php
root 18509 18507 0 12:40 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 18512 18509 8 12:40 ? 00:00:08 /usr/bin/php /var/www/html/cacti/poller.php
root 19651 5977 0 12:41 pts/0 00:00:00 grep poller
root 29055 29053 0 Mar22 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 29057 29055 0 Mar22 ? 00:04:59 /usr/bin/php /var/www/html/cacti/poller.php
root 32670 32669 0 Mar25 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 32671 32670 0 Mar25 ? 00:04:59 /usr/bin/php /var/www/html/cacti/poller.php

Ok so no data retrieving with CLI - Good time, makes sense.
Yes I am getting tons of readdata errors - Old system with map I was troubleshooting with. - "No targets for node"

Just a snippet
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1031] [Map 199] CoreMAX.conf: ReadData: Setting 0,0
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:891] [Map 199] CoreMAX.conf:
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:892] [Map 199] CoreMAX.conf: ReadData for NODE rtr103.mhe.prnynj_cop1:
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:968] [Map 199] CoreMAX.conf: ReadData: No targets for NODE rtr103.mhe.prnynj_cop1
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1031] [Map 199] CoreMAX.conf: ReadData: Setting 0,0
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1035] [Map 199] CoreMAX.conf: ReadData Completed.
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1036] [Map 199] CoreMAX.conf: ------------------------------

[Howie]

Ok so no log for the cli, but poller is running on the new system. I have a few old logs I can go through to find something. I do have a few old hung pollers out there. I will kill them and then start logging fresh again to try and catch when this happens. But like I said I think they are overlapping so not sure if I can catch a trigger. I am having another system built so we can move maps over to it. Maybe I will be able to isolate a few maps at a time without interrupting production.

ps -ef | grep poller
root 9492 9488 0 Mar24 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 9494 9492 0 Mar24 ? 00:05:00 /usr/bin/php /var/www/html/cacti/poller.php
root 13306 13305 0 Mar22 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 13307 13306 0 Mar22 ? 00:04:58 /usr/bin/php /var/www/html/cacti/poller.php
root 13760 13759 0 12:35 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 13761 13760 61 12:35 ? 00:04:07 /usr/bin/php /var/www/html/cacti/poller.php
root 18509 18507 0 12:40 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 18512 18509 8 12:40 ? 00:00:08 /usr/bin/php /var/www/html/cacti/poller.php
root 19651 5977 0 12:41 pts/0 00:00:00 grep poller
root 29055 29053 0 Mar22 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 29057 29055 0 Mar22 ? 00:04:59 /usr/bin/php /var/www/html/cacti/poller.php
root 32670 32669 0 Mar25 ? 00:00:00 /bin/sh -c /usr/bin/php /var/www/html/cacti/poller.php > /dev/null 2>&1
root 32671 32670 0 Mar25 ? 00:04:59 /usr/bin/php /var/www/html/cacti/poller.php

Ok so no data retrieving with CLI - Good time, makes sense.
Yes I am getting tons of readdata errors - Old system with map I was troubleshooting with. - "No targets for node"

Just a snippet
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1031] [Map 199] CoreMAX.conf: ReadData: Setting 0,0
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:891] [Map 199] CoreMAX.conf:
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:892] [Map 199] CoreMAX.conf: ReadData for NODE rtr103.mhe.prnynj_cop1:
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:968] [Map 199] CoreMAX.conf: ReadData: No targets for NODE rtr103.mhe.prnynj_cop1
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1031] [Map 199] CoreMAX.conf: ReadData: Setting 0,0
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1035] [Map 199] CoreMAX.conf: ReadData Completed.
03/24/2017 11:19:26 AM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:1036] [Map 199] CoreMAX.conf: ------------------------------

OK, so to stick with one problem for a second... Are there targets configured for node rtr103.mhe.prnynj_cop1 in CoreMAX.conf? What are they? (if there are, but ReadData thinks there aren't, then there would typically be another error for that node that the TARGET is not recognised, earlier on when the map file is read)

[saguaro]

Yes there are targets in this MAX conf file. I dont understand the naming here but there are 4 live links of of this router. BTW this is the old system and they are updating fine, just trying to get a handle on why the MAX map is adding so much time to the process. Add 200 maps and that is a long time.

NODE rtr103.mhe.prnynj_cop1
LABEL rtr101.mhe.prnynj
ICON images/Router.png
POSITION 1320 167

LINK rtr103.mhe.prnynj_cop1-rtr101.wan.prnynj
WIDTH 4
INFOURL /cacti/graph.php?rra_id=all&local_graph_id=9046&rra_id=all
OVERLIBGRAPH /cacti/graph_image.php?local_graph_id=9046&rra_id=0
TARGET /opt/lampp/htdocs/cacti/rra/rtr101_mhe_prnynj_XX_traffic_in_9467.rrd
NODES rtr103.mhe.prnynj_cop1 rtr101.wan.prnynj
VIA 1081 352
BANDWIDTH 100000M

LINK rtr103.mhe.prnynj_cop1-rtr101.wan.prnynja
WIDTH 4
INFOURL /cacti/graph.php?rra_id=all&local_graph_id=12562&rra_id=all
OVERLIBGRAPH /cacti/graph_image.php?local_graph_id=12562&rra_id=0
TARGET /opt/lampp/htdocs/cacti/rra/rtr101_mhe_prnynj_XX_traffic_in_12991.rrd
NODES rtr103.mhe.prnynj_cop1 rtr101.wan.prnynj
VIA 1089 363
BANDWIDTH 100000M

LINK rtr103.mhe.prnynj_cop1-rtr102.wan.prnynj
WIDTH 4
INFOURL /cacti/graph.php?rra_id=all&local_graph_id=12563&rra_id=all
OVERLIBGRAPH /cacti/graph_image.php?local_graph_id=12563&rra_id=0
TARGET /opt/lampp/htdocs/cacti/rra/rtr101_mhe_prnynj_XX_traffic_in_12992.rrd
NODES rtr103.mhe.prnynj_cop1 rtr102.wan.prnynj
VIA 1321 358
BANDWIDTH 100000M

LINK rtr103.mhe.prnynj_cop1-rtr102.wan.prnynja
WIDTH 4
INFOURL /cacti/graph.php?rra_id=all&local_graph_id=12566&rra_id=all
OVERLIBGRAPH /cacti/graph_image.php?local_graph_id=12566&rra_id=0
TARGET /opt/lampp/htdocs/cacti/rra/rtr101_mhe_prnynj_XX_traffic_in_12995.rrd
NODES rtr103.mhe.prnynj_cop1 rtr102.wan.prnynj
VIA 1303 358
BANDWIDTH 100000M


There is allot of data with debug on, I cant find any errors, don't know if everything is just classified as DEBUG at that point, but no error and one WARNING about time. I cant point to one single event/timestamp that is holding up everything. It is busy not hanging. Is there something specific I should be looking for?


************ It seems to spend more time on these lines for this map and any map for that matter.

03/27/2017 04:21:15 PM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:918] [Map 199] CoreMAX.conf: Will multiply result by 8

*****************************************************************************

Summary / memory looks ok

03/27/2017 04:20:52 PM - WEATHERMAP: Poller[0] Weathermap 0.97a starting - DEBUG mode is on

03/27/2017 04:20:52 PM - WEATHERMAP: Poller[0] DEBUG: [weathermap_memory_check@poller-common.php:11] MEM Initial: memory_get_usage() says 9.1MBytes used. Limit is 1024M
03/27/2017 04:20:52 PM - WEATHERMAP: Poller[0] DEBUG: [weathermap_run_maps@poller-common.php:108] Iterating all maps.
03/27/2017 04:20:52 PM - WEATHERMAP: Poller[0] DEBUG: [weathermap_run_maps@poller-common.php:119] [Map 199] CoreMAX.conf: FIRST TOUCH
03/27/2017 04:20:52 PM - WEATHERMAP: Poller[0] [Map 199] CoreMAX.conf: Map: /opt/lampp/htdocs/cacti/plugins/weathermap/configs/CoreMAX.conf -> /opt/lampp/htdocs/cacti/plugins/weathermap/output/e9219fa4a95ab7f3cf80.html & /opt/lampp/htdocs/cacti/plugins/weathermap/output/e9219fa4a95ab7f3cf80.png

03/27/2017 04:20:52 PM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:863] [Map 199] CoreMAX.conf: Starting prefetch
03/27/2017 04:20:52 PM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:870] [Map 199] CoreMAX.conf: Starting main collection loop
03/27/2017 04:24:23 PM - WEATHERMAP: Poller[0] DEBUG: [SortedImagemap@Weathermap.class.php:3970] [Map 199] CoreMAX.conf: Starting to dump imagemap in reverse Z-order...
03/27/2017 04:25:52 PM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:863] [Map 199] CoreMAX.conf: Starting prefetch
03/27/2017 04:25:52 PM - WEATHERMAP: Poller[0] DEBUG: [ReadData@Weathermap.class.php:870] [Map 199] CoreMAX.conf: Starting main collection loop
Many Lines Laaator-----

03/27/2017 04:24:23 PM - WEATHERMAP: Poller[0] DEBUG: [ProcessString@Weathermap.class.php:517] [Map 199] CoreMAX.conf: Trace: ProcessString(PRNY Core MAX, map)
03/27/2017 04:24:23 PM - WEATHERMAP: Poller[0] WARNING: [Map 199] CoreMAX.conf: TIME: /opt/lampp/htdocs/cacti/plugins/weathermap/configs/CoreMAX.conf took 211 seconds.
03/27/2017 04:24:23 PM - WEATHERMAP: Poller[0] DEBUG: [weathermap_memory_check@poller-common.php:11] [Map 199] CoreMAX.conf: MEM after 0: memory_get_usage() says 14.4MBytes used. Limit is 1024M
03/27/2017 04:24:23 PM - WEATHERMAP: Poller[0] DEBUG: [weathermap_run_maps@poller-common.php:239] Iterated all 1 maps.
03/27/2017 04:24:23 PM - WEATHERMAP: Poller[0] DEBUG: [weathermap_memory_check@poller-common.php:11] MEM Final: memory_get_usage() says 14.4MBytes used. Limit is 1024M
03/27/2017 04:24:23 PM - WEATHERMAP: Poller[0] STATS: Weathermap 0.97a run complete - Mon, 27 Mar 17 16:24:23 -0400: 1 maps were run in 211 seconds with 1 warnings.

[Howie]

So

Code: Select all

NODE rtr103.mhe.prnynj_cop1
LABEL rtr101.mhe.prnynj
ICON images/Router.png
POSITION 1320 167

No was the answer That "no targets for rtr103.mhe.prnynj_cop1" is 100% true.

For the delay after "will multiply...": that's the last line before it asks the plugin to collect data. Tracing through the code though, the next log line would be "SCALING result by..." and then "RRD ReadData: traditional style", and there's no real processing going on between those three. You then get the summary of the rrdtool command that's about to be run, which is where things could slow down.

Without seeing any logs or config file it's not very enticing to faultfind, honestly.

[Howie]

How many links (roughly) are there on this map?

[saguaro]

So I guess my understanding of Targets is incorrect. There are 45 links for 12 nodes in this MAX.conf file. I will PM it to you. Thx

[Howie]

I meant literally - objects with a TARGET line. All nodes and links can have a target, but don't unless you make one.

OK, so 4 seconds per link roughly. Are these crazy large rrd files (like 5 minutes for 3 months), or just the default ones? Apart from the server just being slow (what is the load average? is it swapping?), it shouldn't take that long to read data for one link.

An interesting test would be to look back through that debug log info for one of the rrdtool lines and run it from the command line, to see how long that takes using the 'time' command. (the "rrdtool fetch" command is what I mean)

Thanks for the PM - that will at least allow me to test on my server as a reference.

[saguaro]

Let me look at the files sizes. Dont know what happened to the top of the conf file, this was it.

# Automatically generated by php-weathermap v0.97a

FONTDEFINE 10 VeraBd 7

WIDTH 2000
HEIGHT 1200
HTMLSTYLE overlib
KEYFONT 3
TITLE PRNY Core MAX
HTMLOUTPUTFILE HSD Core.html
IMAGEOUTPUTFILE HSD Core.png
TIMEPOS 131 12 Created: %b %d %Y %H:%M:%S

KEYPOS DEFAULT 26 5 Traffic Load
KEYTEXTCOLOR 0 0 0
KEYOUTLINECOLOR 0 0 0

[saguaro]

Cpu gets up there at first poll kickoff and then settles down a minute later

Tasks: 237 total, 11 running, 221 sleeping, 0 stopped, 5 zombie
Cpu(s): 77.5%us, 17.8%sy, 0.0%ni, 4.6%id, 0.0%wa, 0.0%hi, 0.1%si, 0.0%st
Mem: 16443620k total, 7250236k used, 9193384k free, 647116k buffers
Swap: 8388600k total, 159060k used, 8229540k free, 5622192k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
14730 nobody 15 0 149m 41m 4860 S 8.0 0.3 4305:25 mysqld
4242 root 10 -5 270m 7416 984 S 6.7 0.0 2167:47 tesvc
11112 root 18 0 48968 16m 6604 S 3.0 0.1 0:00.36 php
11155 root 18 0 48172 15m 6604 S 2.7 0.1 0:00.31 php
11241 root 18 0 48692 16m 6604 S 2.7 0.1 0:00.35 php
11106 root 16 0 49172 17m 6812 S 2.3 0.1 0:00.38 php
11109 root 18 0 48204 16m 6692 S 2.3 0.1 0:00.35 php
11119 root 18 0 48176 15m 6604 S 2.3 0.1 0:00.36 php
11140 root 18 0 48440 16m 6604 S 2.3 0.1 0:00.34 php
11193 root 18 0 48452 16m 6604 S 2.3 0.1 0:00.32 php
11215 root 18 0 48688 16m 6604 S 2.3 0.1 0:00.32 php
11127 root 18 0 48440 16m 6604 S 2.0 0.1 0:00.32 php
11173 root 18 0 48452 16m 6692 S 2.0 0.1 0:00.33 php
11266 root 18 0 48428 16m 6604 S 1.7 0.1 0:00.25 php
11322 root 18 0 48176 15m 6604 S 1.3 0.1 0:00.17 php
11351 root 18 0 48176 15m 6604 S 1.3 0.1 0:00.20 php
11379 root 18 0 48168 15m 6604 S 1.3 0.1 0:00.20 php
11295 root 18 0 48176 15m 6604 S 1.0 0.1 0:00.19 php
4372 root 16 0 8924 5696 1272 S 0.7 0.0 115:15.03 sysedge
13946 root 20 0 19540 2168 1080 S 0.7 0.0 0:00.02 snmpget
13956 root 19 0 23740 2320 1208 R 0.7 0.0 0:00.02 snmpget
13960 root 20 0 23740 2316 1208 S 0.7 0.0 0:00.02 snmpget
13961 root 18 0 19540 2160 1080 S 0.7 0.0 0:00.02 snmpget
13962 root 20 0 19544 1988 972 R 0.7 0.0 0:00.02 snmpget
8 root RT -5 0 0 0 S 0.3 0.0 3:04.22 migration/2
11103 root 15 0 12840 1188 804 R 0.3 0.0 0:00.11 top
11406 root 18 0 17760 748 628 S 0.3 0.0 0:00.07 rrdtool
13953 root 20 0 19540 2160 1080 S 0.3 0.0 0:00.01 snmpget
13963 root 20 0 19412 1868 972 R 0.3 0.0 0:00.01 snmpget
13965 root 18 0 19156 1652 972 R 0.3 0.0 0:00.01 snmpget

- Minute later

Tasks: 207 total, 1 running, 201 sleeping, 0 stopped, 5 zombie
Cpu(s): 6.1%us, 6.4%sy, 0.0%ni, 87.5%id, 0.1%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 16443620k total, 7092708k used, 9350912k free, 647116k buffers
Swap: 8388600k total, 159060k used, 8229540k free, 5623644k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
14730 nobody 15 0 149m 41m 4860 S 99.9 0.3 4305:51 mysqld
11106 root 16 0 52940 20m 6980 S 0.3 0.1 0:01.13 php
18284 root 15 0 12840 1172 804 R 0.3 0.0 0:00.02 top
1 root 15 0 10348 604 572 S 0.0 0.0 0:24.67 init


--------------------Manual run of rrdfetch 1 rrd -- the poller goes through all 45 in subsec time


time /usr/bin/rrdtool fetch /opt/lampp/htdocs/cacti/rra/rtr101_wan_prnynj_domain_traffic_in_15289.rrd AVERAGE --start now-800 --end now
traffic_in traffic_out

1490798100: 2.0571832088e+09 3.7493234665e+08
1490798400: 2.0537613461e+09 3.8797780495e+08
1490798700: 2.0643799877e+09 3.9945774762e+08
1490799000: nan nan

real 0m0.002s
user 0m0.001s
sys 0m0.000s

[Howie]

That's good to know. But just to join back up with the PM, there aren't any rrd file targets in the slow map, right?

So now the question is: why does a simple database query take a long time?

For that map (the dssttats max one that is slow), do you have any debug logs? With debug logging on, it should log the actual SQL queries that are being run, so you could try one by hand from the mysql command line tool.

It'll be something like "select rrd_name as name, peak from as result from data_source_stats_weekly"