-
Notifications
You must be signed in to change notification settings - Fork 451
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Mac: prjfs-log improvements #158
Conversation
sanoursa
commented
Aug 13, 2018
- Build prjfs-log under the same scheme as everything else
- Added a utility function for logging vnode actions
- Removed a call to kprintf as it seems to be quite slow
- Added line numbers and timestamps to the output of prjfs-log
…r expanding action bitfield, print line number and timestamp, avoid perf hit of kprintf
@@ -291,6 +291,7 @@ static int HandleVnodeOperation( | |||
{ | |||
if (FileFlagsBitIsSet(currentVnodeFileFlags, FileFlags_IsEmpty)) | |||
{ | |||
KextLog_VnodeOp(currentVnode, vnodeType, procname, action, "Enumerating directory"); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I plan to drop these changes in the kext before merging in. This is just to demonstrate that it is working. With these log statements in place, I see the following outputs when enumerating and hydrating:
(3: 1534195840999) Note: Enumerating directory. Proc name: ls. Directory vnode action:
KAUTH_VNODE_READ_ATTRIBUTES
KAUTH_VNODE_READ_SECURITY
(vnode path: '/Users/sanoursa/GVFSTest/src')
(4: 1534195858026) Note: Hydrating file. Proc name: bash. File vnode action:
KAUTH_VNODE_READ_ATTRIBUTES
KAUTH_VNODE_READ_SECURITY
(vnode path: '/Users/sanoursa/GVFSTest/src/nuget.config')
gettimeofday(&tp, NULL); | ||
long int timestamp = tp.tv_sec * 1000 + tp.tv_usec / 1000; | ||
|
||
printf("(%d: %ld) %s: %.*s\n", lineCount, timestamp, messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader)); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@sanoursa, what was your reason for adding line number to the output?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It just made it easier for me to compare different test runs and compare logs. I added the timestamp later, you could definitely argue that we don't need both. What are your thoughts?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I had been thinking we wouldn't need line numbers (text editors can provide that) but I can seen the benefit now to keeping the line numbers because we expect the log message to contain new lines.
I think we can keep the line numbers in
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yeah, I can see the value in keeping the line numbers. I vote to keep them in too 👍
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Now that you mention it, I think that (multiline traces) is why I added it :-). Hard to remember to the way back from before vacation.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For what it's worth, there is also a timestamp field in the message itself. This is in units of Mach Absolute Time, which is a monotonically increasing clock as opposed to one linked to system time. This time stamp of course also reflects the time when the kernel generated the log message, not when it arrived in the logging daemon. Given we're just outputting seconds here, using the Mach timestamp may be closer to what we want, although I'm of course not exactly sure what it is you do want. One major difference would be that it's not in seconds since midnight, but (nano-)seconds since some arbitrary time, such as the time when the logging daemon started.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ah it probably makes sense to use that then. I just wanted to be able to see relative timings of events. I'll clean that up before merging.
(action & KAUTH_VNODE_WRITE_EXTATTRIBUTES) ? " \n KAUTH_VNODE_WRITE_EXTATTRIBUTES" : "", \ | ||
(action & KAUTH_VNODE_READ_SECURITY) ? " \n KAUTH_VNODE_READ_SECURITY" : "", \ | ||
(action & KAUTH_VNODE_WRITE_SECURITY) ? " \n KAUTH_VNODE_WRITE_SECURITY" : "", \ | ||
(action & KAUTH_VNODE_TAKE_OWNERSHIP) ? " \n KAUTH_VNODE_TAKE_OWNERSHIP" : ""); \ |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
How messy would the output be to separate these with |
rather than newlines?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Depends on the event. Sometimes we'll see 3-4 actions in a single kauth event. I'm not opposed to reformatting this though.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'm good with going what you have now and we can see how it feels in practice
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yep feel free to clean it up if the multiple lines gets to be too much
@@ -24,7 +24,9 @@ int main(int argc, const char * argv[]) | |||
std::cerr << "Failed to set up shared data queue.\n"; | |||
return 1; | |||
} | |||
|
|||
|
|||
__block int lineCount = 0; |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is the __block
required here because of something with Objective-C?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Not Objective-C per se. Apple's C++ compiler has an extension to support blocks, which is how we can call the dispatch_source_set_event_handler
function down below. This __block
flag is required to indicate that you want to be able to modify a variable inside a block.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ahh okay thanks! I missed that dispatch_source_set_event_handler
was in a block.
ad3f3d1
to
9807d51
Compare
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looks good to me.
gettimeofday(&tp, NULL); | ||
long int timestamp = tp.tv_sec * 1000 + tp.tv_usec / 1000; | ||
|
||
printf("(%d: %ld) %s: %.*s\n", lineCount, timestamp, messageType, logStringLength, entry->data + sizeof(KextLog_MessageHeader)); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
For what it's worth, there is also a timestamp field in the message itself. This is in units of Mach Absolute Time, which is a monotonically increasing clock as opposed to one linked to system time. This time stamp of course also reflects the time when the kernel generated the log message, not when it arrived in the logging daemon. Given we're just outputting seconds here, using the Mach timestamp may be closer to what we want, although I'm of course not exactly sure what it is you do want. One major difference would be that it's not in seconds since midnight, but (nano-)seconds since some arbitrary time, such as the time when the logging daemon started.
9c4fbc1
to
34fc540
Compare
Includes changes from microsoft#158 and microsoft#159. Signed-off-by: Derrick Stolee <dstolee@microsoft.com>