POLLER: Poller[0] WARNING: Poller Output Table not Empty

[atelesca]

Hello,
from time to time I have the following error:
POLLER: Poller[0] WARNING: Poller Output Table not Empty.
which results in holes in the graphs (see image attached).
It does not always refer to the same data source, sometimes it is for hdd_used(DS[111]), hdd_total(DS[201]) and sometimes for discards_in(DS[133]), discards_out(DS[133]), errors_out(DS[133]) .
When I launch
php -q poller_output_empty.php

it returns:
There were 0, RRD updates made this pass

How can this error be better debugged?
Thank.
Cheers,
Adriana

[atelesca]

Hello,
I am still fighting with this error but now I have noticed that in the log file of the poller I see the following error:
ERROR: illegal attempt to update using time 1332237541 when last update time is 1332237541 (minimum one second step)
which does not appear in the Cacti log file on the web interface.
Could it be related to the error on the Poller Output table not empty?
This error really prevents me to use Cacti in my system.
Thanks for your help!
Cheers,
Adriana

[gandalf]

This one often is a result of two pollers running in parallel; see 2nd link of my sig
R.

[atelesca]

Thanks a lot for your answer.
I don't receive those errors anymore but that happened after I disabled the thold plugin. I am not sure if this is related but I managed to have a cleaner setup and it looked that things have improved.
Nevertheless, I still have the holes in the graphs although I don't see any error. This happen with data sources retrieved via snmp, never from external scripts. What would you suggest in order to debug this behavior?
Cheers,
Adriana

[gandalf]

You will find some debugging hints at 2nd link of my sig. Hopefully, they will give you more information about the exact issues which may be manyfold
R.

[gandalf]

During a reent investigation of the "poller_output table not empty" issue, I found:
- that related data sources are always related to a Data Query
- all data sources that I found were broken in either
- the related data template had not checked "Index Type", "Index Value", "Output Type ID" and hence an SQL returned wrong results
(e.g. my "old" tenplate for "Alteon Loadbalancers" shows such an issue
- or data template was fine, but there was no (correct) data for those fields entered on the data source
(e.g. a hrStorage ds had no correct indexes given in it's data source)
After fixing those errors, all was fine again.
R.

[stormonts]

I'm not sure I completely understand your response, or how to fix the situation. I did note that most of the issues seem to come from using the systemstats template located here:

http://forums.cacti.net/viewtopic.php?f ... ilit=fridh

Code: Select all

07/16/2012 09:53:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 1774, Data Sources: ssCpuRawNice(DS[11408]), ssCpuRawInterrupt(DS[11408]), ssCpuRawNice(DS[11405]), ssCpuRawUser(DS[11408]), ssCpuRawKernel(DS[11408]), ssCpuRawSoftIRQ(DS[11584]), ssCpuRawNice(DS[11584]), ssCpuRawSoftIRQ(DS[11408]), ssCpuRawSoftIRQ(DS[11461]), ssCpuRawSystem(DS[11408]), ssCpuRawInterrupt(DS[11461]), traffic_out(DS[11774]), ssRawSwapIn(DS[11464]), ssCpuRawKernel(DS[11463]), ssIORawSent(DS[11409]), ssIORawSent(DS[11369]), ssRawSwapIn(DS[11409]), ssRawSwapOut(DS[11409]), ssCpuRawWait(DS[11408]), ssCpuRawSoftIRQ(DS[11463]), Additional Issues Remain. Only showing first 20

Are you saying that the index type for all of our data sources like the one below show be set to "SystemStats" instead of "Index"?

Untitledsd.jpg (107.53 KiB) Viewed 4303 times

[gandalf]

Are you saying that the index type for all of our data sources like the one below show be set to "SystemStats" instead of "Index"?

No. All I wanted to say is, that in _my_ case, the set of "output type ..." was referring to "indexes" that were no longer valid or have never been defined.
R.

[stormonts]

Ok. I attempted to change the items that I noted from "Index" to "systemstats" and the problem still exists. Oh well. Hopefully I can find a fix someday.

[gandalf]

Ok. I attempted to change the items that I noted from "Index" to "systemstats" and the problem still exists. Oh well. Hopefully I can find a fix someday.

Well, IMHO that change was just a shot as you did not say whether this combination of parameters is related to valid data (investigate the data query in question, e.g. by using "Verbose Query" to validate)
R.

[stormonts]

I am really not sure myself. All I know is that the issue didn't exist in .087 then it happened when upgrading to .088. Not sure what changed/why.

[stormonts]

We are back to trying to resolve this issue. More background on the current setup:

Cacti 0.8.8a
Spine 0.8.8a
CentOS 6.4
Poller Type = Spine
Poller Interval = Every Minute
Cron Interval = Every Minute
Maximum Concurrent Poller Processes = 4
Maximum Threads per Process = 70
Number of PHP Script Servers = 6
Script and Server Timeout Value = 10
The Maximum SNMP OID's Per SNMP Get Request = 60
Crontab for "cactiuser"

Code: Select all

* * * * * /usr/bin/php /usr/local/cacti/poller.php --force > /dev/null 2>&1
(We think this is right considering we have a 1 minute poller set, but were not sure if there is a difference between * or */1 in the first column)

Saw this in the processes, but it sound like it is expected:

Code: Select all

1065      7787  7786  0 09:52 ?        00:00:00 /bin/sh -c /usr/bin/php /usr/local/cacti/poller.php --force > /dev/null 2>&1
1065      7788  7787 15 09:52 ?        00:00:09 /usr/bin/php /usr/local/cacti/poller.php --force

Below are the results from the log. As you can see, "most" of the time the poller runs fine, but not every time.

Code: Select all

08/01/2013 10:17:17 AM - SYSTEM STATS: Time:75.3673 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:3267
08/01/2013 10:16:11 AM - SYSTEM STATS: Time:69.5247 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3248
08/01/2013 10:16:02 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 28
08/01/2013 10:15:25 AM - SYSTEM STATS: Time:82.8292 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 10:14:32 AM - SYSTEM STATS: Time:89.9236 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3187
08/01/2013 10:14:02 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 119
08/01/2013 10:13:46 AM - SYSTEM STATS: Time:104.7691 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3252
08/01/2013 10:12:09 AM - SYSTEM STATS: Time:67.9326 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:1761
08/01/2013 10:12:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 3239
08/01/2013 10:11:56 AM - SYSTEM STATS: Time:114.6761 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:2898
08/01/2013 10:11:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 612
08/01/2013 10:10:53 AM - SYSTEM STATS: Time:110.5574 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:2801
08/01/2013 10:10:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 766
08/01/2013 10:09:51 AM - SYSTEM STATS: Time:110.0199 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3234
08/01/2013 10:09:02 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 28
08/01/2013 10:08:52 AM - SYSTEM STATS: Time:110.6611 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3252
08/01/2013 10:07:52 AM - SYSTEM STATS: Time:110.5541 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:2917
08/01/2013 10:07:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 598
08/01/2013 10:06:44 AM - SYSTEM STATS: Time:102.3476 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:2813
08/01/2013 10:06:19 AM - SYSTEM STATS: Time:137.4405 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 10:06:05 AM - SYSTEM STATS: Time:363.3636 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3233
08/01/2013 10:06:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 757
08/01/2013 10:05:57 AM - SYSTEM STATS: Time:175.7508 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 10:05:39 AM - SYSTEM STATS: Time:217.8267 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:2811
08/01/2013 10:03:41 AM - SYSTEM STATS: Time:159.7761 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:1446
08/01/2013 10:03:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 800
08/01/2013 10:02:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 4045
08/01/2013 09:59:35 AM - SYSTEM STATS: Time:32.9827 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:58:34 AM - SYSTEM STATS: Time:32.6191 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:57:34 AM - SYSTEM STATS: Time:32.8716 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:56:31 AM - SYSTEM STATS: Time:29.9406 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:3267
08/01/2013 09:55:29 AM - SYSTEM STATS: Time:28.0092 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:54:33 AM - SYSTEM STATS: Time:31.8059 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:53:37 AM - SYSTEM STATS: Time:35.5749 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:52:42 AM - SYSTEM STATS: Time:41.0037 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:51:35 AM - SYSTEM STATS: Time:33.8641 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:3267
08/01/2013 09:50:35 AM - SYSTEM STATS: Time:32.9149 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:49:34 AM - SYSTEM STATS: Time:32.5205 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:48:40 AM - SYSTEM STATS: Time:39.2518 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:47:37 AM - SYSTEM STATS: Time:36.0945 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:46:35 AM - SYSTEM STATS: Time:33.2099 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:3267
08/01/2013 09:45:41 AM - SYSTEM STATS: Time:39.1493 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:44:42 AM - SYSTEM STATS: Time:40.6817 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3248
08/01/2013 09:43:57 AM - SYSTEM STATS: Time:56.2023 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:42:35 AM - SYSTEM STATS: Time:33.9443 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:41:35 AM - SYSTEM STATS: Time:34.2549 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:3267
08/01/2013 09:40:44 AM - SYSTEM STATS: Time:42.1884 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:39:49 AM - SYSTEM STATS: Time:47.5441 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:38:54 AM - SYSTEM STATS: Time:51.6286 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3248
08/01/2013 09:37:53 AM - SYSTEM STATS: Time:51.9968 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3248
08/01/2013 09:37:00 AM - SYSTEM STATS: Time:58.5425 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:3249
08/01/2013 09:35:38 AM - SYSTEM STATS: Time:36.9770 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:34:40 AM - SYSTEM STATS: Time:38.0758 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:33:44 AM - SYSTEM STATS: Time:42.5877 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:32:56 AM - SYSTEM STATS: Time:54.6570 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:32:16 AM - SYSTEM STATS: Time:74.2825 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7663 RRDsProcessed:3249
08/01/2013 09:32:09 AM - SYSTEM STATS: Time:127.3078 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266
08/01/2013 09:32:01 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty. Issues Found: 28
08/01/2013 09:29:34 AM - SYSTEM STATS: Time:33.0818 Method:spine Processes:4 Threads:70 Hosts:234 HostsPerProcess:59 DataSources:7661 RRDsProcessed:3266

[paulgevers]

Looking at your log, your poller takes too long. It should always be below 60 seconds if you want to poll every minute.

You don't seem to be polling too many hosts, so I would expect there are several hosts timing out or something.

Maybe increase verbosity for a while an see if you can spot failing hosts? I recommend revisiting Gandalfs signature.

[stormonts]

I know that it needs to be below 60 seconds, but I can't figure out what is tripping it up. I have increased the log level to "Debug" level but am not seeing any errors/timeouts or anything like that.

I have followed the links in the signature as well, but none of the suggestions helped.

Currently, the SNMP timeout is set to 1500 for all devices. Should that number be reduced because each device is possibly waiting 1.5 seconds for responses? (or I am misunderstanding that?)

[stormonts]

When I set the log to DEBUG, I see a number of messages like this that correspond to around 30 hosts:

Code: Select all

08/08/2013 10:23:09 AM - SPINE: Poller[0] DEVDBG: SQL:'UPDATE host SET status='3', status_event_count='0', status_fail_date='2013-04-27 13:47:00', status_rec_date='0000-00-00 00:00:00', status_last_error='Host did not respond to SNMP', min_time='9.999990', max_time='3113.573070', cur_time='15.956160', avg_time='19.169621', total_polls='364099', failed_polls='2', availability='99.9995' WHERE id='167''

Does that mean that the last failure was on 4/27/2013 and this isn't an issue that caused the Poller error that soon followed?

Code: Select all

08/08/2013 10:24:02 AM - POLLER: Poller[0] WARNING: Poller Output Table not Empty.  Issues Found: 154, Data Sources: proc(DS[4853]), hdd_total(DS[4854]), hdd_used(DS[4854]), hdd_total(DS[4855]), hdd_used(DS[4855]), cpu(DS[4856]), cpu(DS[4857]), cpu(DS[4858]), cpu(DS[4859]), traffic_in(DS[4860]), traffic_out(DS[4860]), hdd_total(DS[4861]), hdd_used(DS[4861]), hdd_total(DS[4862]), hdd_used(DS[4862]), proc(DS[5092]), hdd_total(DS[5093]), hdd_used(DS[5093]), hdd_total(DS[5094]), hdd_used(DS[5094]), Additional Issues Remain.  Only showing first 20

Would switching to php-snmp make our polling any faster? According to our Cacti Poller statistics, we have:
SNMP - 5820
Scripts - 125
Script Server - 835