[ARVADOS] created: 1.3.0-521-g5b8638861
Git user
git at public.curoverse.com
Wed Mar 13 13:50:16 EDT 2019
at 5b863886118890cc81b728a3a606ea823c836f2b (commit)
commit 5b863886118890cc81b728a3a606ea823c836f2b
Merge: 395b0e17c 89c5953f1
Author: Eric Biagiotti <ebiagiotti at veritasgenetics.com>
Date: Wed Mar 13 13:49:48 2019 -0400
Merge remote-tracking branch 'origin/master' into 14645-fuse-operations-reporting
refs #14645
Arvados-DCO-1.1-Signed-off-by: Eric Biagiotti <ebiagiotti at veritasgenetics.com>
commit 395b0e17c81d2b8767a240193ab94363cbc0dae8
Author: Eric Biagiotti <ebiagiotti at veritasgenetics.com>
Date: Wed Mar 13 13:46:26 2019 -0400
14645: Adds FUSE ops time to crunchstat output
Arvados-DCO-1.1-Signed-off-by: Eric Biagiotti <ebiagiotti at veritasgenetics.com>
Makes stat writing more generic. Now can accommodate different stat counts and types.
diff --git a/services/fuse/arvados_fuse/crunchstat.py b/services/fuse/arvados_fuse/crunchstat.py
index 47d89d8b9..e856d839b 100644
--- a/services/fuse/arvados_fuse/crunchstat.py
+++ b/services/fuse/arvados_fuse/crunchstat.py
@@ -4,57 +4,64 @@
import sys
import time
+from collections import namedtuple
-class Stat(object):
- def __init__(self, prefix, interval,
- egr_name, ing_name,
- egr_func, ing_func):
+Stat = namedtuple("Stat", ['name', 'get'])
+
+class StatWriter(object):
+ def __init__(self, prefix, interval, stats):
self.prefix = prefix
self.interval = interval
- self.egr_name = egr_name
- self.ing_name = ing_name
- self.egress = egr_func
- self.ingress = ing_func
- self.egr_prev = self.egress()
- self.ing_prev = self.ingress()
-
- def update(self):
- egr = self.egress()
- ing = self.ingress()
+ self.stats = stats
+ self.previous_stats = []
+ self.update_previous_stats()
- delta = " -- interval %.4f seconds %d %s %d %s" % (self.interval,
- egr - self.egr_prev,
- self.egr_name,
- ing - self.ing_prev,
- self.ing_name)
+ def update_previous_stats(self):
+ self.previous_stats = [stat.get() for stat in self.stats]
- sys.stderr.write("crunchstat: %s %d %s %d %s%s\n" % (self.prefix,
- egr,
- self.egr_name,
- ing,
- self.ing_name,
- delta))
+ def update(self):
+ def append_by_type(string, name, value):
+ if type(value) is float:
+ string += " %.6f %s" % (value, name)
+ else:
+ string += " %s %s" % (str(value), name)
+ return string
- self.egr_prev = egr
- self.ing_prev = ing
+ out = "crunchstat: %s" % self.prefix
+ delta = "-- interval %.4f seconds" % self.interval
+ for i, stat in enumerate(self.stats):
+ value = stat.get()
+ diff = value - self.previous_stats[i]
+ delta = append_by_type(delta, stat.name, diff)
+ out = append_by_type(out, stat.name, value)
+ sys.stderr.write("%s %s\n" % (out, delta))
+ self.update_previous_stats()
def statlogger(interval, keep, ops):
- calls = Stat("keepcalls", interval, "put", "get",
- keep.put_counter.get,
- keep.get_counter.get)
- net = Stat("net:keep0", interval, "tx", "rx",
- keep.upload_counter.get,
- keep.download_counter.get)
- cache = Stat("keepcache", interval, "hit", "miss",
- keep.hits_counter.get,
- keep.misses_counter.get)
- fuseops = Stat("fuseops", interval,"write", "read",
- ops.write_ops_counter.get,
- ops.read_ops_counter.get)
- blk = Stat("blkio:0:0", interval, "write", "read",
- ops.write_counter.get,
- ops.read_counter.get)
+ calls = StatWriter("keepcalls", interval, [
+ Stat("put", keep.put_counter.get),
+ Stat("get", keep.get_counter.get)
+ ])
+ net = StatWriter("net:keep0", interval, [
+ Stat("tx", keep.upload_counter.get),
+ Stat("rx", keep.download_counter.get)
+ ])
+ cache = StatWriter("keepcache", interval, [
+ Stat("hit", keep.hits_counter.get),
+ Stat("miss", keep.misses_counter.get)
+ ])
+ fuseops = StatWriter("fuseops", interval, [
+ Stat("write", ops.write_ops_counter.get),
+ Stat("read", ops.read_ops_counter.get)
+ ])
+ fusetime = StatWriter("fuseopstime", interval, [
+ Stat("seconds", ops.fuse_ops_total_time)
+ ])
+ blk = StatWriter("blkio:0:0", interval, [
+ Stat("write", ops.write_counter.get),
+ Stat("read", ops.read_counter.get)
+ ])
while True:
time.sleep(interval)
@@ -62,6 +69,7 @@ def statlogger(interval, keep, ops):
net.update()
cache.update()
fuseops.update()
+ fusetime.update()
blk.update()
commit 20a7cf92c668d8d75ca3d1d64f028973a71245d4
Author: Eric Biagiotti <ebiagiotti at veritasgenetics.com>
Date: Wed Mar 13 13:43:03 2019 -0400
14645: Adds FUSE ops timing using prometheus
Arvados-DCO-1.1-Signed-off-by: Eric Biagiotti <ebiagiotti at veritasgenetics.com>
diff --git a/services/fuse/arvados_fuse/__init__.py b/services/fuse/arvados_fuse/__init__.py
index f1e49f5af..7c078858c 100644
--- a/services/fuse/arvados_fuse/__init__.py
+++ b/services/fuse/arvados_fuse/__init__.py
@@ -71,6 +71,7 @@ import ciso8601
import collections
import functools
import arvados.keep
+from prometheus_client import Summary
import Queue
@@ -351,6 +352,27 @@ class Operations(llfuse.Operations):
"""
+ fuse_time = Summary('arvmount_fuse_operations_seconds', 'Time spent during FUSE operations', labelnames=['op'])
+ read_time = fuse_time.labels(op='read')
+ write_time = fuse_time.labels(op='write')
+ destroy_time = fuse_time.labels(op='destroy')
+ on_event_time = fuse_time.labels(op='on_event')
+ getattr_time = fuse_time.labels(op='getattr')
+ setattr_time = fuse_time.labels(op='setattr')
+ lookup_time = fuse_time.labels(op='lookup')
+ forget_time = fuse_time.labels(op='forget')
+ open_time = fuse_time.labels(op='open')
+ release_time = fuse_time.labels(op='release')
+ opendir_time = fuse_time.labels(op='opendir')
+ readdir_time = fuse_time.labels(op='readdir')
+ statfs_time = fuse_time.labels(op='statfs')
+ create_time = fuse_time.labels(op='create')
+ mkdir_time = fuse_time.labels(op='mkdir')
+ unlink_time = fuse_time.labels(op='unlink')
+ rmdir_time = fuse_time.labels(op='rmdir')
+ rename_time = fuse_time.labels(op='rename')
+ flush_time = fuse_time.labels(op='flush')
+
def __init__(self, uid, gid, api_client, encoding="utf-8", inode_cache=None, num_retries=4, enable_write=False):
super(Operations, self).__init__()
@@ -391,6 +413,16 @@ class Operations(llfuse.Operations):
# initializing to continue
self.initlock.set()
+ def fuse_ops_total_time(self):
+ ops_sum = 0.0
+ metrics = self.fuse_time.collect()
+ for metric in metrics:
+ for sample in metric.samples:
+ if sample.name == 'arvmount_fuse_operations_seconds_sum':
+ ops_sum += sample.value
+ return ops_sum
+
+ @destroy_time.time()
@catch_exceptions
def destroy(self):
self._shutdown_started.set()
@@ -417,6 +449,7 @@ class Operations(llfuse.Operations):
[["event_type", "in", ["create", "update", "delete"]]],
self.on_event)
+ @on_event_time.time()
@catch_exceptions
def on_event(self, ev):
if 'event_type' not in ev or ev["event_type"] not in ("create", "update", "delete"):
@@ -447,6 +480,7 @@ class Operations(llfuse.Operations):
self.inodes.inode_cache.find_by_uuid(newowner)):
parent.child_event(ev)
+ @getattr_time.time()
@catch_exceptions
def getattr(self, inode, ctx=None):
if inode not in self.inodes:
@@ -493,6 +527,7 @@ class Operations(llfuse.Operations):
return entry
+ @setattr_time.time()
@catch_exceptions
def setattr(self, inode, attr, fields=None, fh=None, ctx=None):
entry = self.getattr(inode)
@@ -516,6 +551,7 @@ class Operations(llfuse.Operations):
return entry
+ @lookup_time.time()
@catch_exceptions
def lookup(self, parent_inode, name, ctx=None):
name = unicode(name, self.inodes.encoding)
@@ -542,6 +578,7 @@ class Operations(llfuse.Operations):
parent_inode, name)
raise llfuse.FUSEError(errno.ENOENT)
+ @forget_time.time()
@catch_exceptions
def forget(self, inodes):
if self._shutdown_started.is_set():
@@ -552,6 +589,7 @@ class Operations(llfuse.Operations):
if ent.dec_ref(nlookup) == 0 and ent.dead:
self.inodes.del_entry(ent)
+ @open_time.time()
@catch_exceptions
def open(self, inode, flags, ctx=None):
if inode in self.inodes:
@@ -587,6 +625,7 @@ class Operations(llfuse.Operations):
return fh
+ @read_time.time()
@catch_exceptions
def read(self, fh, off, size):
_logger.debug("arv-mount read fh %i off %i size %i", fh, off, size)
@@ -604,6 +643,7 @@ class Operations(llfuse.Operations):
self.read_counter.add(len(r))
return r
+ @write_time.time()
@catch_exceptions
def write(self, fh, off, buf):
_logger.debug("arv-mount write %i %i %i", fh, off, len(buf))
@@ -624,6 +664,7 @@ class Operations(llfuse.Operations):
self.write_counter.add(w)
return w
+ @release_time.time()
@catch_exceptions
def release(self, fh):
if fh in self._filehandles:
@@ -640,6 +681,7 @@ class Operations(llfuse.Operations):
def releasedir(self, fh):
self.release(fh)
+ @opendir_time.time()
@catch_exceptions
def opendir(self, inode, ctx=None):
_logger.debug("arv-mount opendir: inode %i", inode)
@@ -664,6 +706,7 @@ class Operations(llfuse.Operations):
self._filehandles[fh] = DirectoryHandle(fh, p, [('.', p), ('..', parent)] + list(p.items()))
return fh
+ @readdir_time.time()
@catch_exceptions
def readdir(self, fh, off):
_logger.debug("arv-mount readdir: fh %i off %i", fh, off)
@@ -679,6 +722,7 @@ class Operations(llfuse.Operations):
yield (handle.entries[e][0].encode(self.inodes.encoding), self.getattr(handle.entries[e][1].inode), e+1)
e += 1
+ @statfs_time.time()
@catch_exceptions
def statfs(self, ctx=None):
st = llfuse.StatvfsData()
@@ -712,6 +756,7 @@ class Operations(llfuse.Operations):
return p
+ @create_time.time()
@catch_exceptions
def create(self, inode_parent, name, mode, flags, ctx=None):
_logger.debug("arv-mount create: parent_inode %i '%s' %o", inode_parent, name, mode)
@@ -728,6 +773,7 @@ class Operations(llfuse.Operations):
f.inc_ref()
return (fh, self.getattr(f.inode))
+ @mkdir_time.time()
@catch_exceptions
def mkdir(self, inode_parent, name, mode, ctx=None):
_logger.debug("arv-mount mkdir: parent_inode %i '%s' %o", inode_parent, name, mode)
@@ -741,18 +787,21 @@ class Operations(llfuse.Operations):
d.inc_ref()
return self.getattr(d.inode)
+ @unlink_time.time()
@catch_exceptions
def unlink(self, inode_parent, name, ctx=None):
_logger.debug("arv-mount unlink: parent_inode %i '%s'", inode_parent, name)
p = self._check_writable(inode_parent)
p.unlink(name)
+ @rmdir_time.time()
@catch_exceptions
def rmdir(self, inode_parent, name, ctx=None):
_logger.debug("arv-mount rmdir: parent_inode %i '%s'", inode_parent, name)
p = self._check_writable(inode_parent)
p.rmdir(name)
+ @rename_time.time()
@catch_exceptions
def rename(self, inode_parent_old, name_old, inode_parent_new, name_new, ctx=None):
_logger.debug("arv-mount rename: old_parent_inode %i '%s' new_parent_inode %i '%s'", inode_parent_old, name_old, inode_parent_new, name_new)
@@ -760,6 +809,7 @@ class Operations(llfuse.Operations):
dest = self._check_writable(inode_parent_new)
dest.rename(name_old, name_new, src)
+ @flush_time.time()
@catch_exceptions
def flush(self, fh):
if fh in self._filehandles:
-----------------------------------------------------------------------
hooks/post-receive
--
More information about the arvados-commits
mailing list