3 files changed, 72 insertions, 16 deletions
diff --git a/pkg/sentry/fs/file.go b/pkg/sentry/fs/file.go
index b66d2f265..d66813103 100644
--- a/pkg/sentry/fs/file.go
+++ b/pkg/sentry/fs/file.go
@@ -18,6 +18,7 @@ import (
 	"math"
 	"sync"
 	"sync/atomic"
+	"time"
 
 	"gvisor.googlesource.com/gvisor/pkg/amutex"
 	"gvisor.googlesource.com/gvisor/pkg/log"
@@ -33,7 +34,22 @@ import (
 	"gvisor.googlesource.com/gvisor/pkg/waiter"
 )
 
-var reads = metric.MustCreateNewUint64Metric("/fs/reads", false /* sync */, "Number of file reads.")
+var (
+	// RecordWaitTime controls writing metrics for filesystem reads. Enabling this comes at a small
+	// CPU cost due to performing two monotonic clock reads per read call.
+	RecordWaitTime = false
+
+	reads    = metric.MustCreateNewUint64Metric("/fs/reads", false /* sync */, "Number of file reads.")
+	readWait = metric.MustCreateNewUint64Metric("/fs/read_wait", false /* sync */, "Time waiting on file reads, in nanoseconds.")
+)
+
+// IncrementWait increments the given wait time metric, if enabled.
+func IncrementWait(m *metric.Uint64Metric, start time.Time) {
+	if !RecordWaitTime {
+		return
+	}
+	m.IncrementBy(uint64(time.Since(start)))
+}
 
 // FileMaxOffset is the maximum possible file offset.
 const FileMaxOffset = math.MaxInt64
@@ -236,7 +252,12 @@ func (f *File) Readdir(ctx context.Context, serializer DentrySerializer) error {
 //
 // Returns syserror.ErrInterrupted if reading was interrupted.
 func (f *File) Readv(ctx context.Context, dst usermem.IOSequence) (int64, error) {
+	var start time.Time
+	if RecordWaitTime {
+		start = time.Now()
+	}
 	if !f.mu.Lock(ctx) {
+		IncrementWait(readWait, start)
 		return 0, syserror.ErrInterrupted
 	}
 
@@ -246,6 +267,7 @@ func (f *File) Readv(ctx context.Context, dst usermem.IOSequence) (int64, error)
 		atomic.AddInt64(&f.offset, n)
 	}
 	f.mu.Unlock()
+	IncrementWait(readWait, start)
 	return n, err
 }
 
@@ -255,13 +277,19 @@ func (f *File) Readv(ctx context.Context, dst usermem.IOSequence) (int64, error)
 //
 // Otherwise same as Readv.
 func (f *File) Preadv(ctx context.Context, dst usermem.IOSequence, offset int64) (int64, error) {
+	var start time.Time
+	if RecordWaitTime {
+		start = time.Now()
+	}
 	if !f.mu.Lock(ctx) {
+		IncrementWait(readWait, start)
 		return 0, syserror.ErrInterrupted
 	}
 
 	reads.Increment()
 	n, err := f.FileOperations.Read(ctx, f, dst, offset)
 	f.mu.Unlock()
+	IncrementWait(readWait, start)
 	return n, err
 }
 
diff --git a/pkg/sentry/fs/gofer/file.go b/pkg/sentry/fs/gofer/file.go
index 7a6dabba8..631cc80ae 100644
--- a/pkg/sentry/fs/gofer/file.go
+++ b/pkg/sentry/fs/gofer/file.go
@@ -17,6 +17,7 @@ package gofer
 import (
 	"fmt"
 	"syscall"
+	"time"
 
 	"gvisor.googlesource.com/gvisor/pkg/log"
 	"gvisor.googlesource.com/gvisor/pkg/metric"
@@ -32,11 +33,13 @@ import (
 )
 
 var (
-	opensWX   = metric.MustCreateNewUint64Metric("/gofer/opened_write_execute_file", true /* sync */, "Number of times a writable+executable file was opened from a gofer.")
-	opens9P   = metric.MustCreateNewUint64Metric("/gofer/opens_9p", false /* sync */, "Number of times a 9P file was opened from a gofer.")
-	opensHost = metric.MustCreateNewUint64Metric("/gofer/opens_host", false /* sync */, "Number of times a host file was opened from a gofer.")
-	reads9P   = metric.MustCreateNewUint64Metric("/gofer/reads_9p", false /* sync */, "Number of 9P file reads from a gofer.")
-	readsHost = metric.MustCreateNewUint64Metric("/gofer/reads_host", false /* sync */, "Number of host file reads from a gofer.")
+	opensWX      = metric.MustCreateNewUint64Metric("/gofer/opened_write_execute_file", true /* sync */, "Number of times a writable+executable file was opened from a gofer.")
+	opens9P      = metric.MustCreateNewUint64Metric("/gofer/opens_9p", false /* sync */, "Number of times a 9P file was opened from a gofer.")
+	opensHost    = metric.MustCreateNewUint64Metric("/gofer/opens_host", false /* sync */, "Number of times a host file was opened from a gofer.")
+	reads9P      = metric.MustCreateNewUint64Metric("/gofer/reads_9p", false /* sync */, "Number of 9P file reads from a gofer.")
+	readWait9P   = metric.MustCreateNewUint64Metric("/gofer/read_wait_9p", false /* sync */, "Time waiting on 9P file reads from a gofer, in nanoseconds.")
+	readsHost    = metric.MustCreateNewUint64Metric("/gofer/reads_host", false /* sync */, "Number of host file reads from a gofer.")
+	readWaitHost = metric.MustCreateNewUint64Metric("/gofer/read_wait_host", false /* sync */, "Time waiting on host file reads from a gofer, in nanoseconds.")
 )
 
 // fileOperations implements fs.FileOperations for a remote file system.
@@ -232,22 +235,38 @@ func (f *fileOperations) Write(ctx context.Context, file *fs.File, src usermem.I
 	return src.CopyInTo(ctx, f.handles.readWriterAt(ctx, offset))
 }
 
+// incrementReadCounters increments the read counters for the read starting at the given time. We
+// use this function rather than using a defer in Read() to avoid the performance hit of defer.
+func (f *fileOperations) incrementReadCounters(start time.Time) {
+	if f.handles.Host != nil {
+		readsHost.Increment()
+		fs.IncrementWait(readWaitHost, start)
+	} else {
+		reads9P.Increment()
+		fs.IncrementWait(readWait9P, start)
+	}
+}
+
 // Read implements fs.FileOperations.Read.
 func (f *fileOperations) Read(ctx context.Context, file *fs.File, dst usermem.IOSequence, offset int64) (int64, error) {
+	var start time.Time
+	if fs.RecordWaitTime {
+		start = time.Now()
+	}
 	if fs.IsDir(file.Dirent.Inode.StableAttr) {
 		// Not all remote file systems enforce this so this client does.
+		f.incrementReadCounters(start)
 		return 0, syserror.EISDIR
 	}
-	if f.handles.Host != nil {
-		readsHost.Increment()
-	} else {
-		reads9P.Increment()
-	}
 
 	if f.inodeOperations.session().cachePolicy.useCachingInodeOps(file.Dirent.Inode) {
-		return f.inodeOperations.cachingInodeOps.Read(ctx, file, dst, offset)
+		n, err := f.inodeOperations.cachingInodeOps.Read(ctx, file, dst, offset)
+		f.incrementReadCounters(start)
+		return n, err
 	}
-	return dst.CopyOutFrom(ctx, f.handles.readWriterAt(ctx, offset))
+	n, err := dst.CopyOutFrom(ctx, f.handles.readWriterAt(ctx, offset))
+	f.incrementReadCounters(start)
+	return n, err
 }
 
 // Fsync implements fs.FileOperations.Fsync.
diff --git a/pkg/sentry/fs/tmpfs/inode_file.go b/pkg/sentry/fs/tmpfs/inode_file.go
index ef5e67dda..1cc972afa 100644
--- a/pkg/sentry/fs/tmpfs/inode_file.go
+++ b/pkg/sentry/fs/tmpfs/inode_file.go
@@ -17,6 +17,7 @@ package tmpfs
 import (
 	"io"
 	"sync"
+	"time"
 
 	"gvisor.googlesource.com/gvisor/pkg/metric"
 	"gvisor.googlesource.com/gvisor/pkg/sentry/context"
@@ -31,9 +32,10 @@ import (
 )
 
 var (
-	opensRO = metric.MustCreateNewUint64Metric("/in_memory_file/opens_ro", false /* sync */, "Number of times an in-memory file was opened in read-only mode.")
-	opensW  = metric.MustCreateNewUint64Metric("/in_memory_file/opens_w", false /* sync */, "Number of times an in-memory file was opened in write mode.")
-	reads   = metric.MustCreateNewUint64Metric("/in_memory_file/reads", false /* sync */, "Number of in-memory file reads.")
+	opensRO  = metric.MustCreateNewUint64Metric("/in_memory_file/opens_ro", false /* sync */, "Number of times an in-memory file was opened in read-only mode.")
+	opensW   = metric.MustCreateNewUint64Metric("/in_memory_file/opens_w", false /* sync */, "Number of times an in-memory file was opened in write mode.")
+	reads    = metric.MustCreateNewUint64Metric("/in_memory_file/reads", false /* sync */, "Number of in-memory file reads.")
+	readWait = metric.MustCreateNewUint64Metric("/in_memory_file/read_wait", false /* sync */, "Time waiting on in-memory file reads, in nanoseconds.")
 )
 
 // fileInodeOperations implements fs.InodeOperations for a regular tmpfs file.
@@ -249,9 +251,14 @@ func (*fileInodeOperations) StatFS(context.Context) (fs.Info, error) {
 }
 
 func (f *fileInodeOperations) read(ctx context.Context, dst usermem.IOSequence, offset int64) (int64, error) {
+	var start time.Time
+	if fs.RecordWaitTime {
+		start = time.Now()
+	}
 	reads.Increment()
 	// Zero length reads for tmpfs are no-ops.
 	if dst.NumBytes() == 0 {
+		fs.IncrementWait(readWait, start)
 		return 0, nil
 	}
 
@@ -268,6 +275,7 @@ func (f *fileInodeOperations) read(ctx context.Context, dst usermem.IOSequence,
 	size := f.attr.Size
 	f.dataMu.RUnlock()
 	if offset >= size {
+		fs.IncrementWait(readWait, start)
 		return 0, io.EOF
 	}
 
@@ -276,6 +284,7 @@ func (f *fileInodeOperations) read(ctx context.Context, dst usermem.IOSequence,
 	f.attrMu.Lock()
 	f.attr.AccessTime = ktime.NowFromContext(ctx)
 	f.attrMu.Unlock()
+	fs.IncrementWait(readWait, start)
 	return n, err
 }