CPU_TIME counter from USER_STATISTICS gets wrong after some uptime

[Anton Khalikov]

Hi there

We collect user statistics and run "SELECT * FROM INFORMATION_SCHEMA.USER_STATISTICS; FLUSH USER_STATISTICS" every 5 minutes and then put received values to rrd databases. We noticed that after some uptime CPU_TIME counter goes mad and starts to show incredibly high usage values. After restarting MariaDB process it goes back to normal for some time. Please see attached graphs as examples. One can notice a huge drop down of CPU_TIME counter on both graphs. These are graphs for a random customer from two different MariaDB servers.

Platform used: Debian Squeeze amd64, MariaDB 5.2.12-MariaDB-mariadb115~squeeze-log from official package.

[Elena Stepanova (elenst)]

Hi Anton,

Does the counter start showing weird values for all clients simultaneously, or does it happen for one client only?
Is it only CPU_TIME, or other counters go mad too?
Can you provide an example of the data when it _starts_ happening (e.g. two-three snapshots before it shoots up, and two-three snapshots after)? No graphs are necessary, raw data will be fine if it's easier.

Thanks.

[Anton Khalikov (anton-khalikov)]

Hi Elena,

1. Yes, the counter started to show wrong values for all clients simultaneously. Checked over 10 random weekly clients graphs.
2. Yes, it affects only CPU_TIME counter.
3. Do you want me to send you a backup (snapshot of database files) of a random database of a random customer? I can do it but I can't provide sql queries they run unfortunately.

I have about 500 clients on this server and over 1000 on another which was affected too. I am not sure what to send exactly to be honest.

[Elena Stepanova (elenst)]

Hi Anton,

Just to clarify, it started showing *the same* wrong values for all clients simultaneously, right?

[Elena Stepanova (elenst)]

I suppose it's one of the bunch of bugs filed in regard to broken user stats:

https://bugs.launchpad.net/percona-server/+bug/608027
https://bugs.launchpad.net/percona-server/+bug/924872
https://bugs.launchpad.net/percona-server/+bug/728082

Some of them say that a fix is committed in 5.1, so maybe there is something useful to port.
Assigning to Sergei to decide.

[Anton Khalikov (anton-khalikov)]

Hi Elena,

Yes, the values started to be counted wrong for all clients at the same moment (simultaneously). But no, the values are not the same for everyone if you meant that. It looks like MariaDB at some moment started to multiply real CPU_TIME by a factor but this factor is different for every single client. So those who used to have high cpu usage values before the problem occured became to have incredibly high cpu usage values (take a look at second graph, the maximum there is about 14000% which is just impossible), but not every client had so high values.

If you want to know how we calculate these percents, it's simple math. We flush counters every 5 minutes which means 300 seconds. So if a customer's cpu_time within this 5 minutes interval equals to 300 seconds, it's 100%. If cpu_time within 5 minutes only counted to 30 seconds, its 10%. And so on. If a customer has 600 seconds cpu_time within 5 minutes interval it's 200% and means customer's processes used 2 processor cores at 100% each.

Hope this helped.