Remote poller high runtime

[KevinNoall]

I'm having a weird issue with a new remote poller. I've gotten it setup/configured just like my 15 others but on this new instance i'm seeing very long poll times. I have a 1m poll/cron time. When I have no devices configured i am getting .1s poll times. When I have even a single device (even without any graphs) configured I'm getting poller timeouts for exceeding the max time.

I've tried reinstalling a clean DB and setting back up, I've verified bi-direction MYSQL connectivity, etc.

I'm a bit stumped which is expectantly frustrating as I've got many other remote pollers working no problem.

Main poller:
CentOS7, 4cpu, 8GB RAM
Cacti 1.2.16 running Spine
150 devices

New (slow) poller:
CentOS 7, 4cpu, 8GB RAM
Cacti 1.2.16 running Spine
0 devices poll time .1s
1 device no graphs > 60s poll time

Existing working remote poller:
Rasbian Buster on a Pi 3b+ (way less resources than the slow poller!)
Cacti 1.2.16 running Spine
13 devices 40 graphs poll time 7.4s

Any suggestions would be greatly appreciated.

[cigamit]

Logs ?

[KevinNoall]

Here is the log from the remote poller on debug:
Log [Total Lines: 39 - Admin view - Unfiltered]
2020/12/16 19:03:03 - POLLER: Poller[RP-Template] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine/bin/spine, ARGS: -C '/usr/local/spine/etc/spine.conf' --mode=online --poller=999 --first=326 --last=326 --mibs]
2020/12/16 19:03:03 - POLLER: Poller[RP-Template] NOTE: Poller Int: '60', Cron Int: '60', Time Since Last: '60.65', Max Runtime '58', Poller Runs: '1'
2020/12/16 19:03:00 - MAINT Cacti Log Rotation - TIMECHECK Ran: 2020-12-16 00:00:05, Now: 2020-12-16 19:03:00, Next: 2020-12-16 23:59:59
2020/12/16 19:03:00 - POLLER: Poller[RP-Template] NOTE: Registering process! (maintenance, master, 999, 11720)
2020/12/16 19:03:00 - POLLER: Poller[RP-Template] DEBUG: About to Spawn a Remote Process [CMD: /bin/php, ARGS: -q '/var/www/html/cacti/poller_maintenance.php']
2020/12/16 19:03:00 - POLLER: Poller[RP-Template] DEBUG: About to Spawn a Remote Process [CMD: /bin/php, ARGS: -q '/var/www/html/cacti/poller_automation.php' -M]
2020/12/16 19:03:00 - SYSTEM STATS: Time:57.1770 Method:spine Processes:1 Threads:20 Hosts:1 HostsPerProcess:1 DataSources:4 RRDsProcessed:0
2020/12/16 19:03:00 - SYSTEM WARNING: Primary Admin account does not have an email address! Unable to send administrative Email.
2020/12/16 19:03:00 - POLLER: Poller[RP-Template] Maximum runtime of 58 seconds exceeded. Exiting.
2020/12/16 19:02:03 - POLLER: Poller[RP-Template] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine/bin/spine, ARGS: -C '/usr/local/spine/etc/spine.conf' --mode=online --poller=999 --first=326 --last=326 --mibs]
2020/12/16 19:02:02 - POLLER: Poller[RP-Template] NOTE: Poller Int: '60', Cron Int: '60', Time Since Last: '60.46', Max Runtime '58', Poller Runs: '1'
2020/12/16 19:02:00 - MAINT Cacti Log Rotation - TIMECHECK Ran: 2020-12-16 00:00:05, Now: 2020-12-16 19:02:00, Next: 2020-12-16 23:59:59
2020/12/16 19:02:00 - POLLER: Poller[RP-Template] NOTE: Registering process! (maintenance, master, 999, 11707)
2020/12/16 19:02:00 - POLLER: Poller[RP-Template] DEBUG: About to Spawn a Remote Process [CMD: /bin/php, ARGS: -q '/var/www/html/cacti/poller_maintenance.php']
2020/12/16 19:02:00 - POLLER: Poller[RP-Template] DEBUG: About to Spawn a Remote Process [CMD: /bin/php, ARGS: -q '/var/www/html/cacti/poller_automation.php' -M]
2020/12/16 19:02:00 - SYSTEM STATS: Time:56.9177 Method:spine Processes:1 Threads:20 Hosts:1 HostsPerProcess:1 DataSources:4 RRDsProcessed:0
2020/12/16 19:02:00 - SYSTEM WARNING: Primary Admin account does not have an email address! Unable to send administrative Email.
2020/12/16 19:02:00 - POLLER: Poller[RP-Template] Maximum runtime of 58 seconds exceeded. Exiting.
2020/12/16 19:01:03 - POLLER: Poller[RP-Template] DEBUG: About to Spawn a Remote Process [CMD: /usr/local/spine/bin/spine, ARGS: -C '/usr/local/spine/etc/spine.conf' --mode=online --poller=999 --first=326 --last=326 --mibs]
2020/12/16 19:01:03 - POLLER: Poller[RP-Template] NOTE: Poller Int: '60', Cron Int: '60', Time Since Last: '60.73', Max Runtime '58', Poller Runs: '1'
2020/12/16 19:01:00 - MAINT Cacti Log Rotation - TIMECHECK Ran: 2020-12-16 00:00:05, Now: 2020-12-16 19:01:00, Next: 2020-12-16 23:59:59
2020/12/16 19:01:00 - POLLER: Poller[RP-Template] NOTE: Registering process! (maintenance, master, 999, 11680)
2020/12/16 19:01:00 - SYSTEM STATS: Time:56.9132 Method:spine Processes:1 Threads:20 Hosts:1 HostsPerProcess:1 DataSources:4 RRDsProcessed:0
2020/12/16 19:01:00 - SYSTEM WARNING: Primary Admin account does not have an email address! Unable to send administrative Email.
2020/12/16 19:01:00 - POLLER: Poller[RP-Template] Maximum runtime of 58 seconds exceeded. Exiting.
2020/12/16 19:00:00 - SYSTEM STATS: Time:56.9193 Method:spine Processes:1 Threads:20 Hosts:1 HostsPerProcess:1 DataSources:4 RRDsProcessed:0
2020/12/16 19:00:00 - SYSTEM WARNING: Primary Admin account does not have an email address! Unable to send administrative Email.
2020/12/16 19:00:00 - POLLER: Poller[RP-Template] Maximum runtime of 58 seconds exceeded. Exiting.
2020/12/16 18:58:52 - AUTH DEBUG: Using remote client IP Address found in header (REMOTE_ADDR): 172.
2020/12/16 18:58:38 - AUTH DEBUG: Using remote client IP Address found in header (REMOTE_ADDR): 172.
2020/12/16 18:58:03 - SYSTEM STATS: Time:0.1158 Method:spine Processes:1 Threads:20 Hosts:0 HostsPerProcess:0 DataSources:0 RRDsProcessed:0
2020/12/16 18:57:03 - SYSTEM STATS: Time:0.0996 Method:spine Processes:1 Threads:20 Hosts:0 HostsPerProcess:0 DataSources:0 RRDsProcessed:0
2020/12/16 18:56:03 - SYSTEM STATS: Time:0.1271 Method:spine Processes:1 Threads:20 Hosts:0 HostsPerProcess:0 DataSources:0 RRDsProcessed:0
2020/12/16 18:55:03 - SYSTEM STATS: Time:0.0702 Method:spine Processes:1 Threads:20 Hosts:0 HostsPerProcess:0 DataSources:0 RRDsProcessed:0
2020/12/16 18:54:03 - SYSTEM STATS: Time:0.0706 Method:spine Processes:1 Threads:20 Hosts:0 HostsPerProcess:0 DataSources:0 RRDsProcessed:0
2020/12/16 18:53:03 - SYSTEM STATS: Time:0.0702 Method:spine Processes:1 Threads:20 Hosts:0 HostsPerProcess:0 DataSources:0 RRDsProcessed:0
2020/12/16 18:52:03 - SYSTEM STATS: Time:0.0712 Method:spine Processes:1 Threads:20 Hosts:0 HostsPerProcess:0 DataSources:0 RRDsProcessed:0
2020/12/16 18:51:45 - WEBUI NOTE: Cacti Log file /var/www/html/cacti/log/cacti.log, Removed by user admin
2020/12/16 18:51:45 - WEBUI NOTE: Cacti Log Cleared from Web Management Interface.

[Osiris]

Is spine even installed?

Run it in read-only mode from the command line.

[KevinNoall]

[cacti@t-remote-poller etc]$ ../bin/./spine -R
SPINE: Using spine config file [spine.conf]
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The path_php_server variable is /var/www/html/cacti/script_server.php
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The path_cactilog variable is /var/www/html/cacti/log/cacti.log
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The log_destination variable is 1 (FILE)
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The path_php variable is /bin/php
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The availability_method variable is 4
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The ping_recovery_count variable is 3
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The ping_failure_count variable is 4
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The ping_method variable is 1
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The ping_retries variable is 10
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The ping_timeout variable is 600
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The snmp_retries variable is 3
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The log_perror variable is 1
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The log_pwarn variable is 1
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The boost_redirect variable is 1
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The boost_rrd_update_enable variable is 1
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The log_pstats variable is 1
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The threads variable is 20
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The polling interval is 60 seconds
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The number of concurrent processes is 2
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The script timeout is 12
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The selective_device_debug variable is
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The spine_log_level variable is 1
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The number of php script servers to run is 2
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: StartDevice='-1', EndDevice='-1', TotalPHPScripts='1'
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The PHP Script Server is Required
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: The Maximum SNMP OID Get Size is 75
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] Version 1.2.16 starting
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: MySQL is Thread Safe!
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: Spine running as 1000 UID, 0 EUID
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: Spine is running as root.
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: Spine has got ICMP
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] SPINE: Initializing Net-SNMP API
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: Issues with SNMP Header Version information, assuming old version of Net-SNMP.
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] SPINE: Initializing PHP Script Server(s)
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: SS[0] PHP Script Server Routine Starting
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: SS[0] PHP Script Server About to FORK Child Process
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: SS[0] PHP Script Server Child FORK Success
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: SS[0] Confirmed PHP Script Server running using readfd[7], writefd[6]
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: SS[1] PHP Script Server Routine Starting
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: SS[1] PHP Script Server About to FORK Child Process
2020/12/17 08:00:17 - SPINE: Poller[1] PID[22594] DEBUG: SS[1] PHP Script Server Child FORK Success
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: SS[1] Confirmed PHP Script Server running using readfd[9], writefd[8]
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] NOTE: Spine will support multithread device polling.
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: Initial Value of Active Threads is 0
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: Valid Thread to be Created
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: In Poller, About to Start Polling of Device for Device ID 0
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] SPINE: Active Threads is 1, Pending is 1
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] Device[0] HT[1] Total Time: 0.0027 Seconds
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] Device[0] HT[1] DEBUG: HOST COMPLETE: About to Exit Device Polling Thread Function
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: The Value of Active Threads is 0 for Device ID 0
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] POLLER: Active Threads is 0, Pending is 0
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] SPINE: The Final Value of Threads is 0
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: Thread Cleanup Complete
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: SS[0] Script Server Shutdown Started
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: SS[1] Script Server Shutdown Started
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: PHP Script Server Pipes Closed
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: Allocated Variable Memory Freed
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: MYSQL Free & Close Completed
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] DEBUG: Net-SNMP Close Completed
2020/12/17 08:00:18 - SPINE: Poller[1] PID[22594] Time: 0.6625 s, Threads: 20, Devices: 1
[cacti@t-remote-poller etc]$

[TheWitness]

There was a very recent change to lib/functions.php in the 1.2.x branch that you should grab. See if it helps.