Arvados

Is our goal to make use of prometheus' ability to serve stats, or just its aggregation functionality? Is the requirement to provide this data in crunchstat format to improve output or do we already aggregate data based on this output format?

Eric Biagiotti wrote:

Is our goal to make use of prometheus' ability to serve stats, or just its aggregation functionality?

Just the aggregation functionality, if it saves us any effort (someday we might want to export the metrics to a prometheus server, but that's not this story).

Is the requirement to provide this data in crunchstat format to improve output or do we already aggregate data based on this output format?

arv-mount already produces crunchstat format logs and the crunchstat-summary tool already knows how to consume crunchstat logs, so this store is just adding timing metrics.

Ready for review at 97432e0e9d32a41c48a5298a0dbfd70b310e20e7

• Added fuse operation timing using prometheus_client. Added a single Summary metric and individual labels for each operation. This should make querying for total fuse ops timing easier if we use prometheus to serve stats, while also making it possible to look at individual ops.
• Made arvmount crunchstat writing more generic. It can now accommodate different number of stats and types. (i.e. just a single float stat like ops time)

• Increase granularity. Wrap the specific llfuse calls, not the operator function?
• In __init__ update ops counters (write_ops_counter, read_ops_counter) to use prometheus instead of arvados.keep.Counter?

• Set-up environment, ARVADOS_API_TOKEN, etc.
• Set-up a virtualenv
• $ (cd arvados/services/fuse/ && python setup.py install)
• $ mkdir test-dir
• $ arv-mount --crunchstat-interval=1 --foreground --read-write --mount-tmp=tmp test-dir
• In another terminal, cd into the mounted directory and play around. You should see fuseopstime increasing.

Unit Tests: https://ci.curoverse.com/view/Developer/job/developer-run-tests/1125/

crunchstat: fuseopstime 117.273453 seconds -- interval 3.0000 seconds 0.000000 seconds

Format isn't quite right. The format should be:

crunchstat: <category> <value0> <name0> (<value1> <name1>...) --- interval N seconds <deltavalue0> <name0> (<deltavalue1> <name1>...)" 

(I don't know why the name comes after the stat value)

I think we want to log all the individual stats. Some operations interact with the API server, some interact with keep servers, some are cached, some are not. So to diagnose performance problems we need to be able to distinguish where it is spending its time.

I noticed that a single very long operation won't be recorded until it completes. When graphed, the stats may be very spiky -- in other words an operation that takes 40 seconds won't show up as four 10-second intervals of 10 seconds of operation time each, it will show up as 40 seconds of operation time in one interval. I don't know if that can be helped.

Latest at 0e0cbc43912e4bd8ad3fda616e552380d61c3f8d
Unit tests: https://ci.curoverse.com/view/Developer/job/developer-run-tests/1138/

Peter Amstutz wrote:

[...]

Format isn't quite right. The format should be:

Fixed

I think we want to log all the individual stats. Some operations interact with the API server, some interact with keep servers, some are cached, some are not. So to diagnose performance problems we need to be able to distinguish where it is spending its time.

Done and added individual op counts also.

I noticed that a single very long operation won't be recorded until it completes. When graphed, the stats may be very spiky -- in other words an operation that takes 40 seconds won't show up as four 10-second intervals of 10 seconds of operation time each, it will show up as 40 seconds of operation time in one interval. I don't know if that can be helped.

I'll add a feature issue for this so we have it documented.

FYI, most of daa4ee15fdf51a573f96b74c9fd01747b63bbeb0 was changed in the next commit. Keep that in mind if you are going commit by commit.

Also, here is an example of how the prometheus Summary metric is organized. It might be useful for following the logic.

Metric(arvmount_fuse_operations_seconds, 
Time spent during FUSE operations, summary, , [
Sample(name='arvmount_fuse_operations_seconds_count', labels={'op': u'write'}, value=0.0, ...), 
Sample(name='arvmount_fuse_operations_seconds_sum', labels={'op': u'write'}, value=0.0, ...), 
Sample(name='arvmount_fuse_operations_seconds_created', labels={'op': u'write'}, value=0.0, ...), 
Sample(name='arvmount_fuse_operations_seconds_count', labels={'op': u'read'}, value=0.0, ...), 
Sample(name='arvmount_fuse_operations_seconds_sum', labels={'op': u'read'}, value=0.0, ...), 
Sample(name='arvmount_fuse_operations_seconds_created', labels={'op': u'read'}, ...)])]\n" 

The output format is not quite right, the 1st position is the resource being measured, followed by the resource's metrics. So instead of this:

crunchstat: fuseop:count 0 open -- interval 10.0000 seconds 0 open
crunchstat: fuseop:time 0.000000 open -- interval 10.0000 seconds 0.000000 open

It should be something like this:

crunchstat: fuseop:open 0 count 0.000000 time -- interval 10.0000 seconds 0 count 0.000000 time

Peter Amstutz wrote:

The output format is not quite right, the 1st position is the resource being measured, followed by the resource's metrics. So instead of this:

[...]

It should be something like this:

[...]

Fixed in fb8c51a195f2d9603cb129d8c3a21dc5d700aab3
Unit tests: https://ci.curoverse.com/view/Developer/job/developer-run-tests/1140/

crunchstat: fuseop:flush 10 count 0.000100 time -- interval 1.0000 seconds 10 count 0.000100 time
crunchstat: fuseop:on_event 0 count 0.000000 time -- interval 1.0000 seconds 0 count 0.000000 time
crunchstat: fuseop:read 5 count 0.000292 time -- interval 1.0000 seconds 5 count 0.000292 time
crunchstat: fuseop:write 5 count 0.013155 time -- interval 1.0000 seconds 5 count 0.013155 time
...

I also manually added a few fuseop:flush lines to the crunchstat-summary test logs and ran the tests. They obviously break, but the new lines are being processed correctly. A few more decimal places would be nice, but that's for the follow up story #14952.

--- 9,16 ----
  cpu    sys    1.92    0.04    1.92
  cpu    user    3.83    0.09    3.83
  cpu    user+sys    5.75    0.13    5.75
+ fuseop:flush    count    10    10.00    10
+ fuseop:flush    time    0.00    0.00    0.00
  fuseops    read    0    0    0
  fuseops    write    0    0    0
  keepcache    hit    0    0    0

Merged master into this branch to get some unit test fixes at 215d15bc03a38be1965a5d9df21417a3f7eae032
Units tests: https://ci.curoverse.com/view/Developer/job/developer-run-tests/1143/