CPU_TIME is UserStats is broken

Did you see warning at building?
"export LIBS=-lrt" is needed for linux.

> if (opt_userstat_running) {
>#ifdef HAVE_CLOCK_GETTIME
> /* get start cputime */
> if (!(cputime_error = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))
> start_cpu_nsecs = tp.tv_sec*1000000000.0+tp.tv_nsec;
>#else
>#warning : HAVE_CLOCK_GETTIME is disabled.
>#warning : Most systems require librt library to use the function clock_gettime().
>#warning : Did you set environment when ./configure ? (e.g. "export LIBS=-lrt" for sh)
>#endif

since is from RPM is at least a bug in our builds.

Can we get detailed description what was broken and what was fixed ?

Vadim,

In fix I did following (comment from commit):

------
Add set_connections function (related to incomplete port from Google patch) and add call to send_user_stats and send_thread_stats (bug #728082, bug #608027). Without this call statistcs from separated thread didn't aggregated to global_[client|thread|user]_stats.
------

Every thread contains STATS diff_stats structure, which collected information about CPU_Time/other counters after every executed query.
Function "set_connection_stats" extract this information from thread to global_[client|thread|user]_stats.

Port from Google patch was incomplete - set_connection_stats missed, and information doesn't moved from THD to HASH table.

Oleg,

I wonder what it has to do with current bug ?

The original bug was what the time was counted on some platforms but not
others which can't be explained by totally missed code which would make it
never work

On Sun, Jan 29, 2012 at 4:05 PM, Oleg Tsarev <email address hidden>wrote:

> Vadim,
>
> In fix I did following (comment from commit):
>
> ------
> Add set_connections function (related to incomplete port from Google
> patch) and add call to send_user_stats and send_thread_stats (bug #728082,
> bug #608027). Without this call statistcs from separated thread didn't
> aggregated to global_[client|thread|user]_stats.
> ------
>
> Every thread contains STATS diff_stats structure, which collected
> information about CPU_Time/other counters after every executed query.
> Function "set_connection_stats" extract this information from thread to
> global_[client|thread|user]_stats.
>
> Port from Google patch was incomplete - set_connection_stats missed, and
> information doesn't moved from THD to HASH table.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/608027
>
> Title:
> CPU_TIME is UserStats is broken
>
> Status in Percona Server with XtraDB:
> Triaged
> Status in Percona Server 5.1 series:
> Fix Committed
> Status in Percona Server 5.5 series:
> Triaged
>
> Bug description:
> Just noticed this:
>
> mysql> select * from information_schema.user_statistics where
> user="#mysql_system#" \G
> *************************** 1. row ***************************
> USER: #mysql_system#
> TOTAL_CONNECTIONS: 1
> CONCURRENT_CONNECTIONS: 0
> CONNECTED_TIME: 446
> BUSY_TIME: 74
> CPU_TIME: 0
> BYTES_RECEIVED: 0
> BYTES_SENT: 63
> BINLOG_BYTES_WRITTEN: 0
> ROWS_FETCHED: 0
> ROWS_UPDATED: 127576
> TABLE_ROWS_READ: 4085689
> SELECT_COMMANDS: 0
> UPDATE_COMMANDS: 119127
> OTHER_COMMANDS: 89557
> COMMIT_TRANSACTIONS: 90259
> ROLLBACK_TRANSACTIONS: 0
> DENIED_CONNECTIONS: 1
> LOST_CONNECTIONS: 0
> ACCESS_DENIED: 0
> EMPTY_QUERIES: 0
> 1 row in set (0.00 sec)
> [/sql]
>
> The CPU time is 0 which does not sounds right. This is from Percona
> Server RPM on RHEL 5 64bit. Is it compiled with
> proper support ?
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/percona-server/+bug/608027/+subscriptions
>

--
Peter Zaitsev, CEO, Percona Inc.
Tel: +1 888 401 3401 ext 501 Skype: peter_zaitsev
24/7 Emergency Line +1 888 401 3401 ext 911

Percona Live MySQL Conference April 10-12 Santa Clara
http://www.percona.com/live/mysql-conference-2012/

Also additional information. Before fix busy_time/cpu_time from THD collected to global tables just after connection end.
My fix collect this information when you execute SHOW [CLIENT|THREAD|USER]_STATS.

This fix doesn't fix this bug directly. For fix of bug you should compile source code with HAVE_CLOCK_GETTIME.
At least my local build compiled with this option.

My tests doesn't include direct check of CPU time workability (this is required additional debug variables/so one for stable test), and probably our packages build without it.

Can Nacho check this?

Peter,

This is just a head of iceberg. One problem - HAVE_CLOCK_GETTIME, another problem - correct garthering of information together.
This bug originally related to incorrect build (as I think), but we also have problem grab statistics while connection is not closed.

For example, if user application has connection pool, you will see updated statistics just after restart your application.
This is another point, I fixed it in my MP

Oleg,

I understand there could have been multiple problems with original patch.
Yes It is very important to make sure fixes are applied to the
appropriate bug. The current bug is not about statistics not flushed until
clients disconnect - you could have created it as a separate
bug if we do not have such bug already. This is (most likely) about build
bug which is independent from your work. In fact
your work might not have fixed the bug at all if it was build related.

On Sun, Jan 29, 2012 at 6:05 PM, Oleg Tsarev <email address hidden>wrote:

> Peter,
>
> This is just a head of iceberg. One problem - HAVE_CLOCK_GETTIME, another
> problem - correct garthering of information together.
> This bug originally related to incorrect build (as I think), but we also
> have problem grab statistics while connection is not closed.
>
> For example, if user application has connection pool, you will see updated
> statistics just after restart your application.
> This is another point, I fixed it in my MP
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/608027
>
> Title:
> CPU_TIME is UserStats is broken
>
> Status in Percona Server with XtraDB:
> Triaged
> Status in Percona Server 5.1 series:
> Fix Committed
> Status in Percona Server 5.5 series:
> Triaged
>
> Bug description:
> Just noticed this:
>
> mysql> select * from information_schema.user_statistics where
> user="#mysql_system#" \G
> *************************** 1. row ***************************
> USER: #mysql_system#
> TOTAL_CONNECTIONS: 1
> CONCURRENT_CONNECTIONS: 0
> CONNECTED_TIME: 446
> BUSY_TIME: 74
> CPU_TIME: 0
> BYTES_RECEIVED: 0
> BYTES_SENT: 63
> BINLOG_BYTES_WRITTEN: 0
> ROWS_FETCHED: 0
> ROWS_UPDATED: 127576
> TABLE_ROWS_READ: 4085689
> SELECT_COMMANDS: 0
> UPDATE_COMMANDS: 119127
> OTHER_COMMANDS: 89557
> COMMIT_TRANSACTIONS: 90259
> ROLLBACK_TRANSACTIONS: 0
> DENIED_CONNECTIONS: 1
> LOST_CONNECTIONS: 0
> ACCESS_DENIED: 0
> EMPTY_QUERIES: 0
> 1 row in set (0.00 sec)
> [/sql]
>
> The CPU time is 0 which does not sounds right. This is from Percona
> Server RPM on RHEL 5 64bit. Is it compiled with
> proper support ?
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/percona-server/+bug/608027/+subscriptions
>

--
Peter Zaitsev, CEO, Percona Inc.
Tel: +1 888 401 3401 ext 501 Skype: peter_zaitsev
24/7 Emergency Line +1 888 401 3401 ext 911

Percona Live MySQL Conference April 10-12 Santa Clara
http://www.percona.com/live/mysql-conference-2012/

Peter,

I agree. I will fill the bug with description of all found & fixed problems, and I will reassign this bug to Nacho (for check HAVE_CLOCK_GETTIME)

I filled separate bug #924872 and reassign current to Ignacio for check compile flags.

Tested on both PS 5.1 and PS 5.5 RPM builds on CentOS 6.3 64 bit. clock_gettime is used and CPU statistics are collected.

PS 5.5 :

mysql> select * from information_schema.user_statistics\G
*************************** 1. row ***************************
                  USER: root
     TOTAL_CONNECTIONS: 36
CONCURRENT_CONNECTIONS: 0
        CONNECTED_TIME: 1417
             BUSY_TIME: 843
              CPU_TIME: 89
        BYTES_RECEIVED: 36892209
            BYTES_SENT: 0
  BINLOG_BYTES_WRITTEN: 26470995
          ROWS_FETCHED: 8000828
          ROWS_UPDATED: 132874
       TABLE_ROWS_READ: 10727957
       SELECT_COMMANDS: 360206
       UPDATE_COMMANDS: 102888
        OTHER_COMMANDS: 51446
   COMMIT_TRANSACTIONS: 25727
 ROLLBACK_TRANSACTIONS: 0
    DENIED_CONNECTIONS: 0
      LOST_CONNECTIONS: 19
         ACCESS_DENIED: 0
         EMPTY_QUERIES: 0
 TOTAL_SSL_CONNECTIONS: 0
1 row in set (0.00 sec)

PS 5.1:

mysql> select * from information_schema.user_statistics\G
*************************** 1. row ***************************
                  USER: root
     TOTAL_CONNECTIONS: 29
CONCURRENT_CONNECTIONS: 0
        CONNECTED_TIME: 566
             BUSY_TIME: 389
              CPU_TIME: 48
        BYTES_RECEIVED: 10275334
            BYTES_SENT: 21120
  BINLOG_BYTES_WRITTEN: 12192166
          ROWS_FETCHED: 4035649
          ROWS_UPDATED: 110475
       TABLE_ROWS_READ: 6748195
       SELECT_COMMANDS: 3
       UPDATE_COMMANDS: 5
        OTHER_COMMANDS: 16113
   COMMIT_TRANSACTIONS: 16096
 ROLLBACK_TRANSACTIONS: 2
    DENIED_CONNECTIONS: 0
      LOST_CONNECTIONS: 24
         ACCESS_DENIED: 0
         EMPTY_QUERIES: 0
1 row in set (0.00 sec)

Also, tested with strace and gdb:

strace -f -e trace=clock_gettime -p 1698
Process 1698 attached with 19 threads - interrupt to quit
Process 8762 detached
Process 8827 attached
[pid 8827] clock_gettime(0x3 /* CLOCK_??? */, {0, 331874}) = 0
[pid 8827] clock_gettime(0x3 /* CLOCK_??? */, {0, 792574}) = 0
[pid 8827] clock_gettime(0x3 /* CLOCK_??? */, {0, 956722}) = 0
[pid 8827] clock_gettime(0x3 /* CLOCK_??? */, {0, 1228094}) = 0
[pid 8827] clock_gettime(0x3 /* CLOCK_??? */, {0, 17605198}) = 0
[pid 8827] clock_gettime(0x3 /* CLOCK_??? */, {0, 17878064}) = 0

GDB output: http://sprunge.us/ZBdj

Also, CPU_TIME will show up zero for low traffic users since it is not a float or in nanoseconds etc. but in seconds, so to accumulate seconds of cpu_time I did it with sysbench.

Also, checked the binaries themselves with nm and ldd.

 ldd `which mysqld` | grep librt
        librt.so.1 => /lib64/librt.so.1 (0x00007f365e9e1000)

nm -D `which mysqld` | grep clock_gettime
                 U clock_gettime

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1149