Add tracing and Log with usec timestamps #57
Conversation
Print time stamps in the log with usec precision. Fix swiftclient tests to work with new timestamp.
Add calls to logger.Tracef() to help track down file system corruption, timing problems, and slow performance. Update comments for TraceLevelLogging and DebugLevelLogging in sundry config files.
| # Enable debug logging on a per-package basis. Debug logs are disabled by default unless enabled here. | ||
| # Supported values: any combination of "ldlm", "fs", "jrpcfs" and "inode" or "none" (default). | ||
| DebugLevelLogging: none | ||
|
|
There was a problem hiding this comment.
Seems to me this list is very dated... shouldn't we update it?
| @@ -4,7 +4,8 @@ LogFilePath: proxyfsd.log | |||
| # NOTE: Log levels other than Trace and Debug are always on. | |||
|
|
|||
| # Enable trace logging on a per-package basis. Trace logs are disabled by default unless enabled here. | |||
| # Supported values: jrpcfs, inode, none (default). | |||
| # Supported values: any combination of "dlm", "fs", "fuse", "headhunter", "inode", "jrpcfs", "logger", | |||
| # and "swiftclient" or "none" (default). | |||
There was a problem hiding this comment.
Same comment as above... the list of packages may have grown since this was put together...
| @@ -4,7 +4,8 @@ LogFilePath: /var/log/proxyfsd/proxyfsd.log | |||
| # NOTE: Log levels other than Trace and Debug are always on. | |||
|
|
|||
| # Enable trace logging on a per-package basis. Trace logs are disabled by default unless enabled here. | |||
| # Supported values: jrpcfs, inode, none (default). | |||
| # Supported values: any combination of "dlm", "fs", "fuse", "headhunter", "inode", "jrpcfs", "logger", | |||
| # and "swiftclient" or "none" (default). | |||
|
In general, I am no fan of "let's just log/trace everything"... but can be comfortable with it IF-AND-ONLY-IF the tracing is low overhead (particularly when disabled). The current implementation is not alas. So I'm quite nervous about merging this in... |
| @@ -617,6 +657,7 @@ func (vS *volumeStruct) Write(fileInodeNumber InodeNumber, offset uint64, buf [] | |||
| fileInode.AttrChangeTime = updateTime | |||
| fileInode.ModificationTime = updateTime | |||
| fileInode.NumWrites++ | |||
| fileInode.dirty = true | |||
There was a problem hiding this comment.
I am curious - did you have a specific test which was failing that caused you to find this bug?
Or, simply by reading the code did you notice this was not set correctly?
There was a problem hiding this comment.
Oh - I see you just moved it down further with the rest of the changes.
|
|
||
| logger.Tracef("fs.inFlightFileInodeDataTracker(): waiting to flush volume '%s' inode %d", | ||
| logger.Tracef("fs.inFlightFileInodeDataTracker() entry: waiting to flush volume '%s' inode %d", |
There was a problem hiding this comment.
Logger already adds the function name to the log message so you should not have to add the function name here.
There was a problem hiding this comment.
For example, here is an example log message that I see when I am using this PR:
time="2017-12-11T21:00:11.737919Z" level=info msg="vs.Write(): growing file size 999424 to 1000000 volume 'CommonVolume' inode 204 offset 999424 len 576" function=Write goroutine=981 package=inode
This branch is mis-named since it doesn't fix any bugs in the sortedmap code, though that was its genesis.
Add tracing messages to parts of the swiftclient code and the file system code that updates the object map (extent map) and flushes both inodes and B+ trees.