Reimplement ShadowLogger in Rust and bound its memory usage#1325
Reimplement ShadowLogger in Rust and bound its memory usage#1325sporksmith merged 7 commits intoshadow:devfrom
Conversation
Codecov Report
@@ Coverage Diff @@
## dev #1325 +/- ##
==========================================
- Coverage 55.71% 54.27% -1.44%
==========================================
Files 140 138 -2
Lines 20100 20608 +508
Branches 4898 5189 +291
==========================================
- Hits 11199 11186 -13
- Misses 6048 6511 +463
- Partials 2853 2911 +58
Flags with carried forward coverage won't be shown. Click here to find out more.
Continue to review full report at Codecov.
|
7d991cd to
34c7e2b
Compare
robgjansen
left a comment
There was a problem hiding this comment.
Looks reasonable to me! But let's have Steven also look at src/main/core/logger/shadow_logger.rs.
src/main/Cargo.toml
Outdated
| # Alternatively, just call libc's vsprintf directly when the unstable feature | ||
| # `c_variadic` feature is stabilized, or if we decide to enable it anyway. |
There was a problem hiding this comment.
Nit: one too many "feature" words.
src/main/core/logger/log_wrapper.c
Outdated
| return logger; | ||
| } | ||
|
|
||
| void rustlogger_destroy(Logger* logger) { free(logger); } No newline at end of file |
There was a problem hiding this comment.
FYI: I've recently come to appreciate files ending with a blank line rather than the last line not containing a newline. When adding new lines in the future, the diff will show that the previous last line in the file is modified even though the only thing changed was the addition of a newline character.
There was a problem hiding this comment.
Done. Agreed; I'm used to vim doing it automatically. I'll see if there's a VSCode setting...
src/support/logger/logger.c
Outdated
|
|
||
| void logger_setLevel(Logger* logger, LogLevel level) { | ||
| if (!logger) { | ||
|
|
There was a problem hiding this comment.
Was this empty line intentional? If so, and you want to keep the if statement, at least add a comment.
| let total_secs = u64::try_from(total_nanos / 1_000_000_000).unwrap(); | ||
| let total_mins = u32::try_from(total_secs / 60).unwrap(); | ||
| let hours = total_mins / 60; | ||
| let mins = total_mins - hours * 60; | ||
| let secs = total_secs - u64::from(total_mins) * 60; | ||
| let nanos = u64::try_from(total_nanos - u128::from(total_secs) * 1_000_000_000).unwrap(); |
There was a problem hiding this comment.
The difference here between total_* and just hours, mins, etc. is unclear. I'm confused why we are converting from nanos to seconds back to nanos; don't we lose information due to rounding? Probably just needs a comment.
There was a problem hiding this comment.
Added comments and renamed variables to hopefully clarify. Also added a test.
| // we flush the queue on the current thread instead of trying to send to | ||
| // send a command to the logger thread (because our thread-local sender |
| /// entries (e.g. sim time, running process, etc.). It's also designed for | ||
| /// high performance to accomodate heavy logging from multiple threads. | ||
| pub struct ShadowLogger { | ||
| // Channel used to send commands to second commands to the logger's thread. |
There was a problem hiding this comment.
send commands to second commands: it's unclear what this means.
| // Flush *synchronously*, since we're likely about to crash one way or another. | ||
| self.flush_sync(); |
|
@stevenengler I reviewed this but I think you should also review at least |
| line = record | ||
| .line | ||
| .map(|l| format!("{}", l)) | ||
| .as_ref() | ||
| .map(|s| s.as_str()) | ||
| .unwrap_or("n/a"), |
There was a problem hiding this comment.
Maybe just print "-1" instead of "n/a" here if not available to avoid the extra string allocation from format!()?
There was a problem hiding this comment.
Broke up this write! to avoid the allocation while keepin "n/a" instead of "-1".
| fn log(&self, record: &Record) { | ||
| if !self.enabled(record.metadata()) { | ||
| return; | ||
| } |
There was a problem hiding this comment.
Is the individual host log level taken into account anywhere?
There was a problem hiding this comment.
Good catch! It is now :)
| // A lock-free queue for individual log records. We don't put the records | ||
| // themselves in the `command_sender`, because `Sender` doesn't support | ||
| // getting the queue length. Conversely we don't put commands in this queue | ||
| // because it doesn't support blocking operations. | ||
| records: SegQueue<ShadowLogRecord>, |
There was a problem hiding this comment.
Since the logger doesn't push more than SYNC_FLUSH_QD_LINES_THRESHOLD records, does it make sense to make this an ArrayQueue to avoid the extra allocation? Maybe this doesn't matter since there are already a few other string allocations per record.
There was a problem hiding this comment.
Yeah, I think I originally went with SegQueue because I started with a higher value for ASYNC_FLUSH_QD_LINES_THRESHOLD, and didn't want the fixed memory cost. With the current value of 100k it's not so bad, though.
* Replace the wrapper for calling Shadow's logging framework from Rust with a wrapper for calling Rust's logging framework from Shadow. * Add shadow_logger.rs. * Remove shadow_logger.c and its supporting modules. * Delete calls to register threads with logger - no longer needed. * No longer need to explicitly flush between rounds; log records are inserted into a single channel instead of multiple, so we don't need the "synchronization point".
Fixes #1301