Skip to content

Poller items are evaluated too quickly when mixed polling cycles are used #4147

Closed
Closed
Poller items are evaluated too quickly when mixed polling cycles are used#4147
Labels
bugUndesired behaviourresolvedA fixed issue
Milestone
v1.2.17

Description

@thurban
thurban
opened on Feb 25, 2021

I have an issue with a customers Cacti system which was upgraded from 0.8x to Cacti 1.2.16 on Ubuntu.
Data is being polled every 5-Minute. As a preparation for a mixed 1-minute and 5-minute polling the polling interval and cron entry are being changed from 5/5 minutes to 1/1 minute intervals. Afterwards the poller rebuild is being executed to the poller_item is aware of the different setup.

What I expect to see in the table is a nice distribution of the datasources to the different steps. Which is also done correctly:

select count(rrd_next_step) as items,rrd_step,rrd_next_step from poller_item where rrd_next_step<300 group by rrd_next_step,rrd_step;
+-------+----------+---------------+
| items | rrd_step | rrd_next_step |
+-------+----------+---------------+
|  3978 |      300 |           120 |
|  5424 |      300 |           180 |
|  6306 |      300 |           240 |
|  1457 |      300 |             0 |
|  2450 |      300 |            60 |
+-------+----------+---------------+

Also the 1st poller run is the using these 1457 items for the run:

2021/02/24 13:08:17 - SYSTEM STATS: Time:16.0206 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1457 RRDsProcessed:1036

Now it seems like after the polling run, the table gets re-organized, but instead of doing a kind of round-robin (rrd_next_step 60 becomes 0, rrd_next_step 120 becomes 60 ...) it make a complete new combination:

mysql> select count(rrd_next_step) as items,rrd_step,rrd_next_step from poller_item where rrd_next_step<300 group by rrd_next_step,rrd_step;
+-------+----------+---------------+
| items | rrd_step | rrd_next_step |
+-------+----------+---------------+
|  2471 |      300 |            60 |
|  3933 |      300 |           120 |
|  5500 |      300 |           180 |
|  6364 |      300 |           240 |
|  1347 |      300 |             0 |
+-------+----------+---------------+

So the poller pics up the 1347 items for the polling cycle. From my understanding it should have picked up the 2450 items from the original table:

2021/02/24 13:10:01 - SYSTEM STATS: Time:59.5984 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1347 RRDsProcessed:741

Please see the attached file for some more polling cycles.

Nor sure what the reason for this is and cannot remember having seen this behaviour on new installations. Any ideas what this could be or how to fix it ?

Cacti_poller_issue.txt

Activity

  1. TheWitness commented on Feb 25, 2021

    @TheWitness
    TheWitness
    on Feb 25, 2021
    Member

    Thomas,

    From recollection, the poller should only poll those items that have reached 0. If I remember correctly, it was <= 0 as there may have been cases where numbers less than zero were possible. So, every polling cycles, all the numbers should go down by 60 in your case, and when they hit 0, they should be reset to 300. I guess it could be more efficient, like to keep just a number in the settings table that changes and rotates. It would save a lot of I/O.

  2. thurban commented on Feb 26, 2021

    @thurban
    thurban
    on Feb 26, 2021
    ContributorAuthor

    I understand that, my issue is that there are 19615 items that should be polled within the 5 Minute intervall, distributed over 5 1-Minute polls. But If I look at the polling stats there are a lot of items missing:

    2021/02/24 13:08:17 - SYSTEM STATS: Time:16.0206 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1457 RRDsProcessed:1036
2021/02/24 13:10:01 - SYSTEM STATS: Time:59.5984 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1347 RRDsProcessed:741
2021/02/24 13:11:16 - SYSTEM STATS: Time:14.6484 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1328 RRDsProcessed:969
2021/02/24 13:12:13 - SYSTEM STATS: Time:11.9270 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1319 RRDsProcessed:958
2021/02/24 13:13:12 - SYSTEM STATS: Time:10.7443 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1311 RRDsProcessed:958

    So the data sourced being polled total up to 6762 ( the poll at 13:09 was missed by some unknown reason )

    What I would have expected is more like this to happen:

    SYSTEM STATS: Time:16.0206 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:1457 RRDsProcessed:xxx
SYSTEM STATS: Time:59.5984 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:2450 RRDsProcessed:xxx
SYSTEM STATS: Time:14.6484 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:3978 RRDsProcessed:xxx
SYSTEM STATS: Time:11.9270 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:5424 RRDsProcessed:xxx
SYSTEM STATS: Time:10.7443 Method:spine Processes:4 Threads:50 Hosts:4896 HostsPerProcess:1224 DataSources:6306 RRDsProcessed:xxx

    So a changed in the rrd_next_step field would be expected, but not a complete change of the number of items field

  3. TheWitness commented on Feb 27, 2021

    @TheWitness
    TheWitness
    on Feb 27, 2021
    Member

    This seems to be a spine issue. I'm going to make a change. Need you to test the latest 1.2.x branch of spine afterwards.

  4. TheWitness commented on Feb 27, 2021

    @TheWitness
    TheWitness
    on Feb 27, 2021
    Member

    Change is in. Here is the commit. Cacti/spine@03f5acc

  5. TheWitness
    added
    bugUndesired behaviour
    resolvedA fixed issue
    on Feb 27, 2021
  6. TheWitness
    added this to the v1.2.17 milestone on Feb 27, 2021

  7. TheWitness commented on Feb 27, 2021

    @TheWitness
    TheWitness
    on Feb 27, 2021
    Member

    Okay, I did a few spine update, and corrected the 'reporting' issue on poller.php. I've setup a test on my local system, and it appears to work the way I would like it to.

  8. TheWitness
    added a commit that references this issue on Feb 27, 2021

    Fixing ChangeLog for #4147 and fixing #4148

    5314550

  9. TheWitness commented on Feb 28, 2021

    @TheWitness
    TheWitness
    on Feb 28, 2021
    Member

    There was a spine issue though on remote collectors with the new connection pool deallocations routine. It was a typo. Working as expected now.

  10. thurban commented on Feb 28, 2021

    @thurban
    thurban
    on Feb 28, 2021
    ContributorAuthor

    Thanks a lot. Will try to test this today and report back with the results.

  11. TheWitness commented on Feb 28, 2021

    @TheWitness
    TheWitness
    on Feb 28, 2021
    Member

    The new connection pooling in spine should make it a bit faster for remote pollers with several devices, but it's unlikely you will notice it unless the latency is high.

  12. TheWitness commented on Feb 28, 2021

    @TheWitness
    TheWitness
    on Feb 28, 2021
    Member

    Just finished full QA. Was having more issues around spine data collection due to some copy and paste errors.

  13. thurban commented on Mar 1, 2021

    @thurban
    thurban
    on Mar 1, 2021
    ContributorAuthor

    Was trying to compile it on a Ubuntu just now but ran into a compilation issue:

    gcc -DHAVE_CONFIG_H -I. -I./config     -I/usr/include/net-snmp -I/usr/include/net-snmp/.. -I/usr/include/mysql -g -O2 -MT sql.o -MD -MP -MF .deps/sql.Tpo -c -o sql.o sql.c
sql.c: In function ‘db_reconnect’:
sql.c:110:31: warning: format ‘%u’ expects argument of type ‘unsigned int’, but argument 4 has type ‘ulong’ {aka ‘long unsigned int’} [-Wformat=]
  110 |   snprintf(query, 100, "KILL %ul;", mysql_thread);
      |                              ~^     ~~~~~~~~~~~~
      |                               |     |
      |                               |     ulong {aka long unsigned int}
      |                               unsigned int
      |                              %lu
sql.c: In function ‘db_connect’:
sql.c:217:2: error: unknown type name ‘my_bool’; did you mean ‘bool’?
  217 |  my_bool reconnect;
      |  ^~~~~~~
      |  bool
make: *** [Makefile:500: sql.o] Error 1

    Any specific commit/version I should try ?

    Edit: Looks like the mysql version remove the my_bool deifnition: Motion-Project/motion#995

    Edit2: changed the my_bool line to bool and got spine compiled.

  14. thurban commented on Mar 1, 2021

    @thurban
    thurban
    on Mar 1, 2021
    ContributorAuthor

    Getting close, but not as it should be. It looks like the 5 minute polling is being done every 5 minutes now, but in between it looks like it still does the polling of these but just ignores the RRD updates.
    The system currently does not have a single 1-Minute data source configured.

    I was compiling the latest version from https://github.com/Cacti/spine/archive/1.2.x.zip ( b6eba4e253f8f83ceb294becb22c0de662b18c44 )

    Edit: Poller Setting was 1 Minute cron, 1 Minute polling. Cronjob changed to 1 minute. Didn't test with new cacti polling daemon
    . Cacti Version 1.2.16

    mysql> select count(rrd_next_step) as items,rrd_step,rrd_next_step from poller_item where rrd_next_step<300 group by rrd_next_step,rrd_step;
+-------+----------+---------------+
| items | rrd_step | rrd_next_step |
+-------+----------+---------------+
| 19628 |      300 |            60 |
+-------+----------+---------------+
1 row in set (0.01 sec)


mysql> select count(rrd_next_step) as items,rrd_step,rrd_next_step from poller_item where rrd_next_step<300 group by rrd_next_step,rrd_step;
+-------+----------+---------------+
| items | rrd_step | rrd_next_step |
+-------+----------+---------------+
| 19628 |      300 |             0 |
+-------+----------+---------------+
1 row in set (0.08 sec)

mysql> select count(rrd_next_step) as items,rrd_step,rrd_next_step from poller_item where rrd_next_step<400 group by rrd_next_step,rrd_step;
+-------+----------+---------------+
| items | rrd_step | rrd_next_step |
+-------+----------+---------------+
| 19628 |      300 |           300 |
+-------+----------+---------------+
2 rows in set (0.02 sec)

mysql> select count(rrd_next_step) as items,rrd_step,rrd_next_step from poller_item where rrd_next_step<400 group by rrd_next_step,rrd_step;
+-------+----------+---------------+
| items | rrd_step | rrd_next_step |
+-------+----------+---------------+
| 19628 |      300 |           240 |
+-------+----------+---------------+
1 row in set (0.02 sec)

2021/03/01 11:47:48 - SYSTEM STATS: Time:46.7308 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:19628 RRDsProcessed:13455
2021/03/01 11:48:40 - SYSTEM STATS: Time:38.4290 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:0 RRDsProcessed:0
2021/03/01 11:49:36 - SYSTEM STATS: Time:34.1063 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:0 RRDsProcessed:0
2021/03/01 11:50:36 - SYSTEM STATS: Time:34.8326 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:0 RRDsProcessed:0
2021/03/01 11:51:37 - SYSTEM STATS: Time:36.3943 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:0 RRDsProcessed:0
2021/03/01 11:52:38 - SYSTEM STATS: Time:36.2827 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:0 RRDsProcessed:0
2021/03/01 11:53:51 - SYSTEM STATS: Time:48.8856 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:19628 RRDsProcessed:13457
2021/03/01 11:54:47 - SYSTEM STATS: Time:44.5000 Method:spine Processes:1 Threads:100 Hosts:4899 HostsPerProcess:4899 DataSources:0 RRDsProcessed:0

  15. TheWitness commented on Mar 12, 2021

    @TheWitness
    TheWitness
    on Mar 12, 2021
    Member

    @thurban, can you send me your personal email. All I have is your commercial support email.

  16. thurban commented on Mar 12, 2021

    @thurban
    thurban
    on Mar 12, 2021
    ContributorAuthor

    send you an email to your cacti.net mail address

  17. TheWitness commented on Apr 3, 2021

    @TheWitness
    TheWitness
    on Apr 3, 2021
    Member

    I think this is the correct behavior. So, I'm going to close this. The one thing that is tricky with the poller interval and the cron interval, is that when you change it, you have to completely repopulate your poller cache to get the items completely redistributed properly. We can revisit this at a later date.

  18. TheWitness
    closed this as completedon Apr 3, 2021
  19. netniV
    changed the title [-]poller_items gets re-calculated with every poll when 1-minute and 5-minute data sources are mixed[/-] [+]Poller items are evaluated too quickly when mixed polling cycles are used[/+] on Apr 12, 2021
  20. github-actions
    locked and limited conversation to collaborators on Jul 12, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugUndesired behaviourresolvedA fixed issue

    Type

    No type

    Projects

    No projects

      Milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions