take a timestamp when a console logging message happens#85
Conversation
|
For posterity I'd like to mention an alternative that I wondered about but discarded. Rather than modifying the output handler signature to always include an rcutils timestamp (some handlers might want a different type of time to rcutils system time, or not care at all), the signature could instead be left as is and any output handlers interested in time would have to call now() themselves. The issue is that if multiple handlers are attached they might get called sequentially, in which case you want them to all have access to the time of the original call, not the time that the handler got called. Similarly, handlers that use sim time, for example, will want the sim time of the original call as well, not when the handler was called. Since rcutils doesn't "know" about sim time, I imagine the sim timestamp would be passed to the log call in the 'context' dictionary that we have previously spoken about log calls including one day. |
dhood
left a comment
There was a problem hiding this comment.
LGTM other than a small bug; could you add/extend a test to cover this? eg https://github.com/ros2/rcutils/pull/53/files#diff-4783eea3d9e98e3d3b03afdb62839106R36
src/logging.c
Outdated
| } else if (strcmp("seconds", token) == 0) { | ||
| if (snprintf( | ||
| numeric_storage, sizeof(numeric_storage), | ||
| "%f", timestamp / 1e9) == 0) |
There was a problem hiding this comment.
You're right, but maybe <= 0? If it returns zero then it means it wrote no bytes, which also seems like an issue.
There was a problem hiding this comment.
I don't think I can test this case, since I get no feedback (other than output to stderr) when this occurs (there's no return code from the function).
That's a good point, I sort of thought about that when I was deciding whether or not have a steady time stamp too. On the one hand you really want all timestamps to agree whether you log to file, console or rosout, so that would indicate take the timestamp at the time of the log call and pass it to the output handlers. On the other, someone might want, system time, steady time, or sim time. So this pr was sort of an incremental step between where we have system time and in the future we could add more timestamps or require the output handlers to get their own various timestamps themselves. |
|
I'm happy to change this pr how ever you think would be best. I just opened it because I wanted to see how much time passed between logs. I'll fix the failing tests (sort of fragile since they will break anytime the file has new lines added above a certain point, but unavoidable I think). |
|
I agree that this is in the right direction. To me the contents of the PR are fine now, it's just the missing test coverage that I think should be addressed before merging |
|
The new output format tokens aren't currently tested: could you please add/extend a test to cover this? Here are the other ones that check formatting: https://github.com/ros2/rcutils/pull/53/files#diff-4783eea3d9e98e3d3b03afdb62839106R36 |
src/logging.c
Outdated
| goto cleanup; | ||
| } | ||
| token_expansion = numeric_storage; | ||
| } else if (strcmp("nanoseconds", token) == 0) { |
There was a problem hiding this comment.
I guess users might use {seconds}.{nanoseconds} but then get confused by the variable nature of digits of the nanoseconds part. I think an additional placeholder is desired / necessary which pads the output with leasing zeros to a fixed length of 9 digits.
There was a problem hiding this comment.
I think you're confusing the purpose of {nanoseconds}, it's the total timestamp in nanoseconds, not the nanoseconds part of time. {seconds} is floating point time. So, {seconds}.{nanoseconds} doesn't really make any sense. See the documentation:
https://github.com/ros2/rcutils/pull/85/files#diff-f1d39d4e841937fde043a8e49b7e6c2aR62
There was a problem hiding this comment.
Oh, got it now. Thanks for clarifying.
There was a problem hiding this comment.
that was how I also first interpreted it (as sec.nanosec), so if it's happened to a few people maybe there's a way we can rename it to avoid confusion. We could just do time like in ROS 1 and additionally time_ns? Then you'd be less likely to think {time}.{time_ns}, but 'time' is not as descriptive as we'd like moving forward..
There was a problem hiding this comment.
It's a fair point, however, that the padding is never considered. So on the floating point on the seconds may not be consistent from machine to machine. I'll see what I can do about that, as ideally it would be similar.
I'm actually writing the missing test right now, I so I'll think if a fixed padding makes sense in either case.
There was a problem hiding this comment.
It doesn't need to be concise I don't think, we could use timestamp and timestamp_as_nanoseconds.
There was a problem hiding this comment.
@dhood and I talked about it offline and we decided on time and time_as_nanoseconds, using time rather than timestamp to be closer to what ROS 1 does, and using _as_nanoseconds to be maximumly specific without worrying about verbosity too much because we expect it to not be used that much in favor of the floating point seconds version.
|
I factored out the conversion of the timepoints to public functions with tests. They now print fixed width, so for the nanoseconds always 20 characters (19 digits and either a I also fixed the logging tests, only the last test case was being checked due to a logical bug in the test. I also fixed a cmake style (though lint_cmake made me indent it weird) and prevented some "error being overwritten" messages in some of the tests. Those aren't really an issue, but it's nice to search for them in the CI output periodically and these were false positives. |
include/rcutils/time.h
Outdated
| * The number is always fixed width, with left padding zeros up to the maximum | ||
| * number of digits the timepoint can represent. | ||
| * Right now that is 19 digits (so 19 characters) for a signed 64-bit integer. | ||
| * Positive timepoint values will have a leading space, whereas negative values |
There was a problem hiding this comment.
I understand that the motivation for this is so that positive and negative outputs are aligned, but isn't that only going to be necessary in like 0.1% of use cases? I think the small use case of swapping between negative and positive timestamps and wanting them to be aligned doesn't warrant the extraneous space for 99.9% of use cases (I might be missing something though). Having the default output be [ 123.456] is surprising to me.
There was a problem hiding this comment.
I understand that the motivation for this is so that positive and negative outputs are aligned, but isn't that only going to be necessary in like 0.1% of use cases?
That's right, I had reservations about it too, but given I made these changes in the first place in order to try and keep a fixed width I was placing extreme value on never having a different string length. However, the case pointed out for floats (variable mantissa) is far more likely and the case I'm optimizing for here should honestly never happen (that's why I originally made the timepoint unsigned 😛).
I can change this.
There was a problem hiding this comment.
+1 for having the default misaligned for positive/negative numbers, if the misalignment bothers someone they can add an option for it 😄 I know we pad in some cases in ros1 e.g. [ERROR] vs [ INFO] but those are much more likely.
include/rcutils/time.h
Outdated
| * | ||
| * \param[in] timepoint the time to be made into a string | ||
| * \param[out] str the output string in which it is stored | ||
| * \param[in] str_size the output string in which it is stored |
There was a problem hiding this comment.
this doc line is copypasta (and below)
src/time.c
Outdated
| RCUTILS_CHECK_ARGUMENT_FOR_NULL(str, RCUTILS_RET_INVALID_ARGUMENT, allocator) | ||
| if (*timepoint >= 0) { | ||
| // have an explicit leading space to align with negative values which start with `-` | ||
| if (rcutils_snprintf(str, str_size, " %.19" PRId64, *timepoint) <= 0) { |
There was a problem hiding this comment.
If str_size was specified as 1, the snprintf's return value will be 0 from my understanding ("The number of characters that would have been written if n had been sufficiently large, not counting the terminating null character."). I don't think we should error in that case anymore. However, there's a test below for str_size=1 that expects RCUTILS_RET_OK, is that test passing?
There was a problem hiding this comment.
All of the tests are passing (and running 😄) from what I can tell. As well as on Windows where the snprintf like functions some times behave slightly differently.
I think that it will return 21 or whatever it would have been, regardless of the value of str_size, rather than returning how many it actually wrote based on truncating due to str_size being smaller than the result.
There was a problem hiding this comment.
ohhh, I see. it will successfully put (0 chars + NUL) but won't return 0. good good, this clears it up, thanks
| @@ -0,0 +1 @@ | |||
| '[\s,-][0-9]{10}[.][0-9]{9}' '[\s,-][0-9]{19}'\n'[\s,-][0-9]{10}[.][0-9]{9}' '[\s,-][0-9]{19}' No newline at end of file | |||
There was a problem hiding this comment.
\s instead of will also match other whitespace characters which seems unnecessarily loose. Was there a reason for not just using a space?
There was a problem hiding this comment.
Nope, I can change that and rerun the tests.
There was a problem hiding this comment.
no need now I was mostly just curious if there was regex trickery going on
dcff0da to
4c53fff
Compare
|
Ok, I rebased and addressed the comments, waiting for re-review before CI. |
|
Also have to make a new rclcpp pr because I messed that up, and fix rclpy warnings, before CI. |
src/time.c
Outdated
| RCUTILS_SET_ERROR_MSG("failed to format time point into string as float seconds", allocator) | ||
| return RCUTILS_RET_ERROR; | ||
| } | ||
| // if (*time_point >= 0) { |
dirk-thomas
left a comment
There was a problem hiding this comment.
The PR mixes two different things:
- adding a timestamp to the log event
- various unrelated test changes / improvements
It would be good to have these changes in two separate commits for easier review as well as after the merge as separate commits for history.
| * Negative values will have a leading `-`, so they will be one character | ||
| * longer than the positive values. | ||
| * | ||
| * The recommended minimum size of the input string is 32 characters, but |
There was a problem hiding this comment.
How is this "recommended minimum size" relevant in the docblock? Isn't is sufficient to document the exact max size necessary? Also why 32?
Same below.
There was a problem hiding this comment.
Because the usable block size on my machine is 16 bytes, and 32 is the smallest multiple of that in which the exact size of this string fits. Also, it gives us a little flexibility for the future, e.g. if we wanted to add + to the front of the time to distinguish it from -. Not saying we will, but if when you ask for 21 characters malloc gives you 32 anyways...
This is the program I used to check:
#include <cassert>
#include <cstdio>
#if __linux__
#include <malloc.h>
#else
#include <malloc/malloc.h>
#endif
int main()
{
uint8_t * bytes = (uint8_t *)malloc(1);
assert(bytes);
#if __linux__
printf("%zu\n", malloc_usable_size(bytes));
#else
printf("%zu\n", malloc_size(bytes));
#endif
return 0;
}I didn't try it on Windows.
|
there are failing windows tests in case you didn't notice @wjwwood |
f2256f7 to
5404867
Compare
|
@wjwwood I rebased and addressed the two comments if you want to take a look at those commits at some point |
|
Changes lgtm, thanks @dhood! |
|
Thanks for pushing this through @dhood! |
|
nooo problem! |
|
Wiki updates: |
Also make it available for console formatting.