Percona MySQL templates, Cacti 0.8.7i, InnoDB I/O, query clearly works, but graphs are all NaN

[Jay Libove]

I’m pulling my hair out. I’ve got the new Percona MySQL templates (thanks Baron!) installed on my Cacti 0.8.7i server.

 

I enabled the InnoDB I/O template. In the cacti log I see this every five minutes:

 

02/19/2012 07:45:05 PM - CMDPHP: Poller[0] Host[3] DS[79] WARNING: Result from CMD not valid.  Partial Result: U

02/19/2012 07:45:05 PM - CMDPHP: Poller[0] Host[3] DS[79] CMD: /usr/bin/php -q /var/www/cacti/scripts/ss_get_mysql_stats.php --host h1766939.stratoserver.net --items gh,gi,gj,gk --user cactiquery --pass 'password' --port 3306, output: U

02/19/2012 07:45:05 PM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool update /var/www/cacti/rra/webnovias_file_fsyncs_79.rrd --template 1329677104:U

 

But when I run the data collection command manually, it works perfectly:

 

$ php -q /var/www/cacti/scripts/ss_get_mysql_stats.php --host h1766939.stratoserver.net --items gh,gi,gj,gk --user cactiquery --pass 'password' --port 3306 --nocache

gh:6344889 gi:25529983 gj:18322886 gk:5124662

 

I’m not sure where to look, other than in cacti.log (which is where the above output came from), to see why the poller is unhappy with this apparently good output from the ss_get_mysql_stats.php script… suggestions?

 

Thanks,

Jay

 

[Baron Schwartz]

Jay,

This looks like some problem such as cache file permissions or what have you.  Have you followed the troubleshooting steps from the FAQ?  If I were diagnosing it and couldn't figure out from the FAQ, I'd enable the verbose logging in the PHP script.

-- 
You received this message because you are subscribed to the Google Groups "Percona Discussion" group.
To post to this group, send email to percona-d...@googlegroups.com.
To unsubscribe from this group, send email to percona-discuss...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/percona-discussion?hl=en.

- Baron

--

Chief Performance Architect at Percona <http://www.percona.com/>
+1 (888) 401-3401 x507
Calendar: <https://tungle.me/percona_baron>
Percona Live MySQL Conference & Expo <http://www.percona.com/live>

[Jay Libove]

Hi Baron,
Sorry, yes, I've followed the Cacti troubleshooting FAQ. I found
nothing wrong.
In particular, the cache files' permissions are correct.

I've run the ss_get_mysql_stats.php script with a matching
ss_get_mysql_stats.php.cnf configuration file enabling debug logging
to a /tmp/ file.
Here's (I think) the relevant output:
2012-02-24 08:50:03 at /var/www/cacti/scripts/ss_get_mysql_stats.php:
116
'g0:308091593 g1:7644997 g2:2376550 g3:1645536 g4:2813 g5:419464637
g6:1 g7:4 g8:0 g9:0 ga:65535 gb:0 gc:65194 gd:125 ge:3805351 gf:31462
gg:2444327 gh:1276991 gi:3805540 gj:3547404 gk:1046091 gl:0 gm:0 gn:0
go:0 gp:0 gq:1 gr:0 gs:0 gt:0 gu:58620 gv:59208 gw:55938 gx:379572 gy:
5118713 gz:176661 h0:717830 h1:361324 h2:18390 h3:292699519 h4:822
h5:241941969 h6:94 h7:495 h8:400 h9:10176 ha:300 hb:2500 hc:400 hd:0
he:3 hf:61 hg:0 hh:0 hi:6 hj:194938 hk:4 hl:500 hm:0 hn:194939 ho:-1
hp:-1 hq:0 hr:-1 hs:0 ht:0 hu:0 hv:0 hw:0 hx:0 hy:0 hz:0 i0:0 i1:0
i2:171406417 i3:7297 i4:1811997 i5:168580181 i6:400933 i7:2945 i8:0
i9:1 ia:46 ib:0 ic:0 id:57504 ie:0 if:152303 ig:0 ih:994999 ii:48 ij:
66313 ik:82334958 il:578712 im:485226 in:291700 io:102 ip:193431416958
iq:37494234173 ir:4194304 is:0 it:61762332792 iu:61762332792 iv:-1 iw:
32768 ix:0 iy:0 iz:-1 j0:2 j1:0 j2:-1 j3:-1 j4:-1 j5:-1 j6:-1 j7:-1
j8:-1 j9:-1 ja:-1 jb:-1 jc:-1 jd:-1 je:-1 jf:-1 jg:4 jh:1 ji:16843949
jj:51176 jk:0 jl:0 jm:207399080 jn:247488938 jo:75547439 jp:0 jq:
57281414 jr:7559991303 js:8 jt:0 ju:0 jv:412006 jw:99266473 jx:2 jy:0
jz:2212673 k0:0 k1:1098907648 k2:0 k3:51648 k4:1 k5:33201 k6:33203
k7:-1 k8:-1 k9:-1 ka:-1 kb:-1 kc:-1 kd:-1 ke:-1 kf:-1 kg:0 kh:5174272
ki:8388608 kj:6674 kk:209 kl:-1 km:-1 kn:-1 ko:-1 kp:-1 kq:-1 kr:-1
ks:-1 kt:-1 ku:-1 kv:-1 kw:-1 kx:-1 ky:-1 kz:-1 la:-1 lb:-1 lc:-1
ld:-1 le:-1 lf:-1 lg:-1 lh:-1 li:-1 lj:-1 lk:-1 ll:-1 lm:-1'
2012-02-24 08:50:03 at /var/www/cacti/scripts/ss_get_mysql_stats.php:
133
array (
0 => 'Final result',
1 =>
array (
0 => 'gh:1276991',
1 => 'gi:3805540',
2 => 'gj:3547404',
3 => 'gk:1046091',
),
)

So that seems to be working to actually acquire the data from the
monitored host.

And here's a related bit out of cacti.log:
02/24/2012 08:50:03 AM - CMDPHP: Poller[0] Host[3] PING: UDP Ping
Success (1.42 ms)
02/24/2012 08:50:03 AM - CMDPHP: Poller[0] Host[3] DS[79] WARNING:

Result from CMD not valid. Partial Result: U

02/24/2012 08:50:03 AM - CMDPHP: Poller[0] Host[3] DS[79] CMD: /usr/

bin/php -q /var/www/cacti/scripts/ss_get_mysql_stats.php --host
h1766939.stratoserver.net --items gh,gi,gj,gk --user cactiquery --pass
'password' --port 3306, output: U

02/24/2012 08:50:04 AM - POLLER: Poller[0] CACTI2RRD: /usr/bin/rrdtool
update /var/www/cacti/rra/webnovias_file_fsyncs_79.rrd --template
1330069803:U


Clearly, something's wrong between the ss_get_mysql_stats.php (which
seems to be working) and how the poller gets the output of
ss_get_mysql_stats.php to try to hand it off to rrdtool.
But I don't know where to look for it...

Thanks!
-Jay

[Jay Libove]

A bit further information about the rrd:

$ rrdtool fetch /var/www/cacti/rra/webnovias_file_fsyncs_79.rrd MAX
log_writes file_reads
file_writes file_fsyncs

1329985200: nan nan nan nan
1329985500: nan nan nan nan
1329985800: nan nan nan nan
1329986100: nan nan nan nan
1329986400: nan nan nan nan
1329986700: nan nan nan nan
...
(every 300 seconds)
...
1330070400: nan nan nan nan
1330070700: nan nan nan nan
1330071000: nan nan nan nan
1330071300: nan nan nan nan
1330071600: nan nan nan nan

[Baron Schwartz]

Jay,

On Feb 24, 2012, at 3:13 AM, Jay Libove wrote:

> Hi Baron,
> Sorry, yes, I've followed the Cacti troubleshooting FAQ. I found
> nothing wrong.
> In particular, the cache files' permissions are correct.
>
> I've run the ss_get_mysql_stats.php script with a matching
> ss_get_mysql_stats.php.cnf configuration file enabling debug logging
> to a /tmp/ file.
> Here's (I think) the relevant output:

I'd suggest letting the debug setting run in production. It's not harmful; just don't leave it forever or you'll fill your hard drive. You never know what's different between the way you're running the script manually and how Cacti is doing it.

[Jay Libove]

Once again, I apologise for not saying so before - I've been running in production with debug setting on for quite some time. The results are always the same :(

Okay, so now I've hacked ~cacti/cmd.php to add a bunch of debugging output around the call to the data collection script, approx line number 521, as follows:

                        case POLLER_ACTION_SCRIPT: /* script (popen) */
cacti_log("about to call exec_poll(" . $item["arg1"] . ")\n");
/*                              $output = trim(exec_poll($item["arg1"])); */
                                $output = exec_poll($item["arg1"]);
cacti_log("output is ". $output . "\n");
                                $output = trim($output);
cacti_log("output trimmed is " . $output . "\n");

                                /* remove any quotes from string */
                                $output = strip_quotes($output);
cacti_log("output with quotes stripped is " . $output . "\n");

                                if (!validate_result($output)) {
                                        if (strlen($output) > 20) {
                                                $strout = 20;
                                        } else {
                                                $strout = strlen($output);
                                        }
cacti_log("output length is " . $strout . "\n");
                                        cacti_log("Host[$host_id] DS[$data_source] WARNING: Result from CMD not valid.  Partial Result: " . substr($output, 0, $strout), $print_data_to_stdout);


Here is the output produced:
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] Host[3] PING: UDP Ping Success (1.67 ms)
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] about to call exec_poll(/usr/bin/php -q /var/www/cacti/scripts/ss_get_mysql_stats.php --host h1766939.stratoserver.net --items gh,gi,gj,gk --user cactiquery --pass 'password' --port 3306)
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] output is
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] output trimmed is
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] output with quotes stripped is
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] output length is 1
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] Host[3] DS[79] WARNING: Result from CMD not valid.  Partial Result: U
02/25/2012 01:15:04 PM - CMDPHP: Poller[0] Host[3] DS[79] CMD: /usr/bin/php -q /var/www/cacti/scripts/ss_get_mysql_stats.php --host h1766939.stratoserver.net --items gh,gi,gj,gk --user cactiquery --pass 'password' --port 3306, output: U

Did I get the debugging output PHP commands wrong, so that I'm not displaying the actual output of the exec_poll() call correctly?
Or do I surmise accurately that the exec_poll() call results are not being properly received by the PHP code in cmd.php ?

Thanks,
-Jay

On Friday, 24 February 2012 14:42:25 UTC+1, Baron Schwartz wrote:

Jay,

[Baron Schwartz]

Jay,

I'm not sure whether you're doing the right thing here in the code, but let me verify something first. There is a debug setting for the script that's shipped with the Percona monitoring plugins -- and you are using this.  There is also a logging verbosity setting for Cacti itself which should do what you're trying to do in code changes to cmd.php.

Baron

--
You received this message because you are subscribed to the Google Groups "Percona Discussion" group.

To view this discussion on the web visit https://groups.google.com/d/msg/percona-discussion/-/VKwLa3I7Y6cJ.

To post to this group, send email to percona-d...@googlegroups.com.
To unsubscribe from this group, send email to percona-discuss...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/percona-discussion?hl=en.

[Jay Libove]

Baron wrote:

I'm not sure whether you're doing the right thing here in the code, but let me verify something first. There is a debug setting for the script that's shipped with the Percona monitoring plugins -- and you are using this.  There is also a logging verbosity setting for Cacti itself which should do what you're trying to do in code changes to cmd.php.

Yes, I've been using both the Percona mysql monitoring plugin per-script .cnf file $debug setting AND also the Cacti general debug configuration, all along.
-Jay
 

[Jay Libove]

Still having the same problem here. (Been away from working on it for a while).

I can run the ss_get_mysql_stats.php command manually, and it returns reasonable values. e.g.:

$ php /var/www/cacti/scripts/ss_get_mysql_stats.php --host webnoviasTEMP.opus5.net --items gh,gi,gj,gk --user cactiquery --pass 'AGq$Df!8' --port 3306

gh:953 gi:757 gj:1593 gk:428

I've followed the debugging suggestions, checked the rrd file permissions - all that stuff is in this thread history. What I can't figure out is why the graphs under Cacti remain blank/NaN.

Could someone please review this thread history and help me pick up and figure this out?

Thanks,

Jay

[David Juntgen]

Jay - sounds silly but if your grabbing for straws then try clearing your browser cache.

--Dave

--

You received this message because you are subscribed to the Google Groups "Percona Discussion" group.

To view this discussion on the web visit https://groups.google.com/d/msg/percona-discussion/-/pKN9NEjeCLgJ.

To post to this group, send email to percona-d...@googlegroups.com.
To unsubscribe from this group, send email to percona-discuss...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/percona-discussion?hl=en.

--
David W. Juntgen

[Jay Libove]

 

Dave wrote:

>Jay - sounds silly but if your grabbing for straws then try clearing your browser cache.

Thanks for the thought, Dave.  No, sadly, it’s not that.  I think this really is some complex bad interaction between the Percona MySQL scripts (which do seem to execute and produce good data) and Cacti/RRD which apparently doesn’t like that data!

Anyone able to assist?

Thanks,
Jay

 

[mark....@neonova.net]

I'm having the EXACT SAME PROBLEM with Cacti 1.10.  Something clearly isn't right.