[BUG] Query times inserted in exponential notation

[azilber]

I'm seeing data put into the pinba tables as exponential notation. The data itself is incorrect as queries aren't actually taking such a long time, and it's messing up Pinboard:

I've had a bug opened on pinboard: intaro/pinboard#86 but I realize this seems to be a bug with either the php extension (master branch), or the engine (also master branch).

[tony2001]

Please do a SELECT * FROM and show the output here.

[azilber]

Very strange, the exponential data seems to come and go from the report_by_status table. For the other tables it's still there....

MariaDB [pinba]> select * FROM report_by_status limit 10;
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+--------+------------------------+--------------------------+-----------------+-------------+
| req_count | req_per_sec | req_time_total | req_time_percent | req_time_per_sec | ru_utime_total | ru_utime_percent | ru_utime_per_sec | ru_stime_total | ru_stime_percent | ru_stime_per_sec | traffic_total | traffic_percent | traffic_per_sec | status | memory_footprint_total | memory_footprint_percent | req_time_median | index_value |
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+--------+------------------------+--------------------------+-----------------+-------------+
|       793 |  3.40282e38 |        744.815 |          99.9927 |       3.40282e38 |        340.729 |          99.9976 |       3.40282e38 |       0.174593 |              100 |       3.40282e38 |       339.125 |         99.9258 |      3.40282e38 |    200 |                2567640 |                  99.8072 |       0.0114076 | 200         |
|         2 |  3.40282e38 |       0.054347 |       0.00729618 |       3.40282e38 |          0.008 |       0.00234785 |       3.40282e38 |              0 |                0 |             NULL |      0.251953 |       0.0742399 |      3.40282e38 |    302 |                   4960 |                 0.192801 |       0.0292969 | 302         |
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+--------+------------------------+--------------------------+-----------------+-------------+
2 rows in set (0.00 sec)

echo 'select * FROM report_by_status;' |mysql pinba
req_count   req_per_sec req_time_total  req_time_percent    req_time_per_sec    ru_utime_total  ru_utime_percent    ru_utime_per_sec    ru_stime_total  ru_stime_percent    ru_stime_per_sec    traffic_total   traffic_percent traffic_per_sec status  memory_footprint_total  memory_footprint_percent    req_time_median index_value
779 0.86845 744.594 99.9927 0.830093    340.709 99.9977 0.379832    0.177783    100 0.154395    337.758 99.9255 0.376542    200 2543370 99.8054 0.0114768   200
2   0.00222965  0.054347    0.00729835  0.0000605875    0.008   0.00234799  0.00000891862   0   0   0   0.251953    0.0745402   0.000280884 302 4960    0.194637    0.0292969   302

MariaDB [pinba]> select * from report_by_script_name limit 10;
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+-----------------------------+------------------------+--------------------------+-----------------+-----------------------------+
| req_count | req_per_sec | req_time_total | req_time_percent | req_time_per_sec | ru_utime_total | ru_utime_percent | ru_utime_per_sec | ru_stime_total | ru_stime_percent | ru_stime_per_sec | traffic_total | traffic_percent | traffic_per_sec | script_name                 | memory_footprint_total | memory_footprint_percent | req_time_median | index_value                 |
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+-----------------------------+------------------------+--------------------------+-----------------+-----------------------------+
|         1 |  3.40282e38 |       0.053481 |       0.00719296 |       3.40282e38 |          0.012 |       0.00352596 |       3.40282e38 |          0.004 |       0.00288983 |       3.40282e38 |      0.130859 |       0.0449489 |      3.40282e38 | /                           |                   4020 |                 0.158954 |       0.0585938 | /                           |
|         1 |  3.40282e38 |        0.38675 |        0.0520162 |       3.40282e38 |       0.128007 |        0.0376123 |       3.40282e38 |       0.012001 |        0.0086702 |       3.40282e38 |       36.3848 |         12.4978 |      3.40282e38 | /?id=104                    |                   5428 |                 0.214628 |        0.390625 | /?id=104                    |
|         1 |  3.40282e38 |       0.250458 |        0.0336855 |       3.40282e38 |       0.048002 |        0.0141044 |       3.40282e38 |       0.012001 |        0.0086702 |       3.40282e38 |        29.668 |         10.1907 |      3.40282e38 | /?id=1040                   |                   5276 |                 0.208618 |        0.253906 | /?id=1040                   |
|         1 |  3.40282e38 |       0.217325 |        0.0292293 |       3.40282e38 |       0.036003 |        0.0105788 |       3.40282e38 |          0.016 |        0.0115593 |       3.40282e38 |       29.7148 |         10.2068 |      3.40282e38 | /?id=141                    |                   5300 |                 0.209567 |        0.234375 | /?id=141                    |
|         1 |  3.40282e38 |       0.507488 |        0.0682549 |       3.40282e38 |       0.116007 |        0.0340863 |       3.40282e38 |       0.012001 |        0.0086702 |       3.40282e38 |         33.96 |         11.6649 |      3.40282e38 | /?id=2718&src=articlexpromo |                   5532 |                  0.21874 |        0.507812 | /?id=2718&src=articlexpromo |
|         2 |  3.40282e38 |        0.56079 |        0.0754238 |       3.40282e38 |       0.128007 |        0.0376123 |       3.40282e38 |          0.008 |        0.0115593 |       3.40282e38 |       38.5781 |         13.2512 |      3.40282e38 | /?id=284                    |                   8140 |                 0.321863 |       0.0390625 | /?id=284                    |
|       688 |  3.40282e38 |        741.466 |          99.7239 |       3.40282e38 |        339.853 |           99.859 |       3.40282e38 |       0.201082 |           99.948 |       3.40282e38 |       120.145 |         41.2685 |      3.40282e38 | /process.php                |                2335160 |                  92.3344 |       0.0116443 | /process.php                |
|         1 |  3.40282e38 |       0.053288 |         0.007167 |       3.40282e38 |          0.012 |       0.00352596 |       3.40282e38 |              0 |                0 |             NULL |      0.130859 |       0.0449489 |      3.40282e38 | /robots.txt                 |                   3736 |                 0.147725 |       0.0585938 | /robots.txt                 |
|        45 |  3.40282e38 |       0.023113 |        0.0031086 |       3.40282e38 |              0 |                0 |             NULL |              0 |                0 |             NULL |       2.41699 |        0.830214 |      3.40282e38 | /xyzzyx.php                 |                 156432 |                  6.18546 |      0.00954861 | /xyzzyx.php                 |
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+-----------------------------+------------------------+--------------------------+-----------------+-----------------------------+
9 rows in set (0.00 sec)

[tony2001]

How can I reproduce it?

[azilber]

I used the master branch of pinba_extension compiled as a module for php 5.2.10.
Also, used master branch of pinba_engine. I also have a tcpdump from port 30002. I can it to you, but I can't post that public.

[tony2001]

I also use both, but I don't observe any problems like this.
I need a reproduce case or at least a description of how to do it, otherwise there's not much I can do about it.
Start with simple php -r 'echo 1;' and see if you can reproduce the problem.

[azilber]

I'm also using MariaDB 10.0.12 for the db. I ran the php code... output seems fine:

|         5 |  0.00558036 |       0.026292 |       0.00556847 |     0.0000293437 |              0 |                0 |                0 |              0 |                0 |                0 |    0.00488281 |      0.00489908 |   0.00000544957 | unknown                        | -                               |                   7480 |                 0.622692 |      0.00976562 | unknown/-                                          |
|         1 |  0.00111607 |       0.000216 |     0.0000457473 |   0.000000241071 |              0 |                0 |                0 |              0 |                0 |                0 |      0.144531 |        0.145013 |     0.000161307 | unknown                        | unknown                         |                   1496 |                 0.124538 |       0.0195312 | unknown/unknown                                    |

also this:

MariaDB [pinba]> select * from report_by_server_and_schema where server_name ='unknown'\G
*************************** 1. row ***************************
               req_count: 21
             req_per_sec: 0.0234375
          req_time_total: 0.008282
        req_time_percent: 0.000486606
        req_time_per_sec: 0.0000092433
          ru_utime_total: 0
        ru_utime_percent: 0
        ru_utime_per_sec: 0
          ru_stime_total: 0
        ru_stime_percent: 0
        ru_stime_per_sec: 0
           traffic_total: 0.0205078
         traffic_percent: 0.0100874
         traffic_per_sec: 0.0000228882
             server_name: unknown
                  schema: 
  memory_footprint_total: 31416
memory_footprint_percent: 2.66932
         req_time_median: 0.0093006
             index_value: :unknown
1 row in set (0.00 sec)

I did see it once in exponential notation though. I ran php again though and it was overwritten. It seems it happens only occasionally, but when it does it corrupts the Intaro pinba data.

[azilber]

I just rebuilt pinba_engine with the latest MariaDB 10.0.13. It's fresh data, and it's happening again. I'm thinking the issue is with the extension. We need to limit the size of the floating point numbers that get inserted. We should never have exponential form in the database.

MariaDB [pinba]> select * from report_by_server_and_schema;
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+--------------------------------+--------+------------------------+--------------------------+-----------------+---------------------------------+
| req_count | req_per_sec | req_time_total | req_time_percent | req_time_per_sec | ru_utime_total | ru_utime_percent | ru_utime_per_sec | ru_stime_total | ru_stime_percent | ru_stime_per_sec | traffic_total | traffic_percent | traffic_per_sec | server_name                    | schema | memory_footprint_total | memory_footprint_percent | req_time_median | index_value                     |
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+--------------------------------+--------+------------------------+--------------------------+-----------------+---------------------------------+
|         3 |  3.40282e38 |       0.002098 |       0.00130267 |       3.40282e38 |              0 |                0 |             NULL |              0 |                0 |             NULL |      0.161133 |       0.0190119 |      3.40282e38 | 0.0.0.0                        |        |                  13324 |                  13.7741 |      0.00651042 | :0.0.0.0                        |
|         2 |  3.40282e38 |        1.54405 |         0.958716 |       3.40282e38 |           0.02 |        0.0886784 |       3.40282e38 |          0.004 |         0.199589 |       3.40282e38 |        1.3623 |        0.160737 |      3.40282e38 | pm.dev1.nnnn.com |        |                   8468 |                  8.75408 |       0.0390625 | :pm.dev1.nnnn.com |
|         8 |  3.40282e38 |        158.003 |          98.1057 |       3.40282e38 |        21.6013 |          95.7787 |       3.40282e38 |        0.49553 |          98.9022 |       3.40282e38 |       732.574 |         86.4357 |      3.40282e38 | pm.dev2.nnnn.com |        |                  64516 |                  66.6956 |        0.234375 | :pm.dev2.nnnn.com |
|         1 |  3.40282e38 |        1.50467 |         0.934266 |       3.40282e38 |       0.932058 |          4.13267 |       3.40282e38 |       0.036001 |         0.898174 |       3.40282e38 |       113.439 |         13.3846 |      3.40282e38 | wwwdev.nnnn.com             |        |                  10424 |                  10.7762 |         1.52344 | :wwwdev.nnnn.com             |     
+-----------+-------------+----------------+------------------+------------------+----------------+------------------+------------------+----------------+------------------+------------------+---------------+-----------------+-----------------+--------------------------------+--------+------------------------+--------------------------+-----------------+---------------------------------+
4 rows in set (0.00 sec)