| Message ID | 20230809155438.22470-4-rf@opensource.cirrus.com (mailing list archive) |
|---|---|
| State | New |
| Delegated to: | Brendan Higgins |
| Headers | show |
| Series | kunit: Add dynamically-extending log | expand |
On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald <rf@opensource.cirrus.com> wrote: > > Add handling to kunit_log_append() for log messages that are longer than > a single buffer fragment. > > The initial implementation of fragmented buffers did not change the logic > of the original kunit_log_append(). A consequence was that it still had > the original assumption that a log line will fit into one buffer. > > This patch checks for log messages that are larger than one fragment > buffer. In that case, kvasprintf() is used to format it into a temporary > buffer and that content is then split across as many fragments as > necessary. > > Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com> > --- I think this looks good (and is a long-overdue addition to the logging functionality). One thought I have (and I'm kicking myself for not thinking of it earlier) is that this is starting to get very similar to the "string stream" functionality in lib/kunit/string-stream.{h,c}. Now, I actually think this implementation is much more efficient (using larger fragments, whereas the string stream uses variable-sized ones). Particularly since there are a lot of cases where string streams are created, converted to a string, and then logged, there's almost certainly a bunch of redundant work being done here. My gut feeling is that we should stick with this as-is, and maybe try to either work out some better integration between string streams and logging (to avoid that extra string allocation) or find some way of combining them. Regardless, this seems good as-is to me. There are some minor comments below, but nothing disastrous. I'll let Rae have a look over the various strscpy and strlcat calls, though, as while I did check them carefully (and KASAN hasn't complained), it's always best to have as many eyes on C string code as possible. :-) But in my eyes, this is Reviewed-by: David Gow <davidgow@google.com> Cheers, -- David > lib/kunit/test.c | 65 +++++++++++++++++++++++++++++++++++++++++++++--- > 1 file changed, 61 insertions(+), 4 deletions(-) > > diff --git a/lib/kunit/test.c b/lib/kunit/test.c > index dfe51bc2b387..28d0048d6171 100644 > --- a/lib/kunit/test.c > +++ b/lib/kunit/test.c > @@ -140,25 +140,82 @@ static struct kunit_log_frag *kunit_log_extend(struct list_head *log) > return frag; > } > > +static void kunit_log_append_string(struct list_head *log, const char *src) > +{ > + struct kunit_log_frag *frag, *new_frag; > + int log_len, bytes_left; > + ssize_t written; > + char *p; > + > + frag = list_last_entry(log, struct kunit_log_frag, list); > + log_len = strlen(frag->buf); > + bytes_left = sizeof(frag->buf) - log_len; > + > + written = strscpy(frag->buf + log_len, src, bytes_left); > + if (written != -E2BIG) > + goto newline; > + > + src += bytes_left - 1; > + do { > + new_frag = kunit_log_extend(log); > + if (!new_frag) > + goto newline; > + > + frag = new_frag; > + written = strscpy(frag->buf, src, sizeof(frag->buf)); > + src += sizeof(frag->buf) - 1; > + } while (written == -E2BIG); > + > +newline: > + if (written == -E2BIG) I think that this can only be true if kunit_log_extend() fails. If the do/while loop ends naturally, then written != -E2BIG, as is the case with the strscpy goto above. Do you think it's cleaner to move the 'written = strlen(frag->buf) into the if (!new_frag) statement within the loop? > + written = strlen(frag->buf); > + > + p = &frag->buf[written - 1]; > + if (*p != '\n') { > + if (strlcat(frag->buf, "\n", sizeof(frag->buf)) >= sizeof(frag->buf)) { > + frag = kunit_log_extend(log); > + if (!frag) { A comment here could be useful. Something like "If we can't extend the log to add a newline, truncate the last message". > + *p = '\n'; > + return; > + } > + > + frag->buf[0] = '\n'; > + frag->buf[1] = '\0'; > + } > + } > +} > + > /* Append formatted message to log, extending the log buffer if necessary. */ > void kunit_log_append(struct list_head *log, const char *fmt, ...) > { > va_list args; > struct kunit_log_frag *frag; > int len, log_len, len_left; > + char *tmp = NULL; > > if (!log) > return; > > - frag = list_last_entry(log, struct kunit_log_frag, list); > - log_len = strlen(frag->buf); > - len_left = sizeof(frag->buf) - log_len - 1; > - > /* Evaluate length of line to add to log */ > va_start(args, fmt); > len = vsnprintf(NULL, 0, fmt, args) + 1; > va_end(args); > > + if (len > sizeof(frag->buf) - 1) { > + va_start(args, fmt); > + tmp = kvasprintf(GFP_KERNEL, fmt, args); > + va_end(args); > + Should we handle the case where kvasprintf() fails here and drop the log message? > + kunit_log_append_string(log, tmp); > + kfree(tmp); > + > + return; > + } > + > + frag = list_last_entry(log, struct kunit_log_frag, list); > + log_len = strlen(frag->buf); > + len_left = sizeof(frag->buf) - log_len - 1; > + > if (len > len_left) { > frag = kunit_log_extend(log); > if (!frag) > -- > 2.30.2 >
On 10/8/23 15:38, David Gow wrote: > On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald > <rf@opensource.cirrus.com> wrote: >> >> Add handling to kunit_log_append() for log messages that are longer than >> a single buffer fragment. >> >> The initial implementation of fragmented buffers did not change the logic >> of the original kunit_log_append(). A consequence was that it still had >> the original assumption that a log line will fit into one buffer. >> >> This patch checks for log messages that are larger than one fragment >> buffer. In that case, kvasprintf() is used to format it into a temporary >> buffer and that content is then split across as many fragments as >> necessary. >> >> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com> >> --- > > I think this looks good (and is a long-overdue addition to the logging > functionality). > > One thought I have (and I'm kicking myself for not thinking of it > earlier) is that this is starting to get very similar to the "string > stream" functionality in lib/kunit/string-stream.{h,c}. Now, I > actually think this implementation is much more efficient (using > larger fragments, whereas the string stream uses variable-sized ones). > Particularly since there are a lot of cases where string streams are > created, converted to a string, and then logged, there's almost > certainly a bunch of redundant work being done here. > > My gut feeling is that we should stick with this as-is, and maybe try > to either work out some better integration between string streams and > logging (to avoid that extra string allocation) or find some way of > combining them. > I completely failed to notice string_stream. I could re-implement this to use string_stream. I wonder whether appending newlines gets a bit inefficient with the current string_stream implementation. Could add newline support to string_stream and alloc one extra byte for each fragment just in case we need to add a newline. The string_stream implementation would waste a lot a memory if you log many short lines. My current code wastes memory if you log lots of lines that don't fit in available space in the current fragment - though it's simple to shuffle the formatted string backwards to fill up the previous fragment (I just haven't done that yet).
On Thu, Aug 10, 2023 at 9:38 AM David Gow <davidgow@google.com> wrote: > > On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald > <rf@opensource.cirrus.com> wrote: > > > > Add handling to kunit_log_append() for log messages that are longer than > > a single buffer fragment. > > > > The initial implementation of fragmented buffers did not change the logic > > of the original kunit_log_append(). A consequence was that it still had > > the original assumption that a log line will fit into one buffer. > > > > This patch checks for log messages that are larger than one fragment > > buffer. In that case, kvasprintf() is used to format it into a temporary > > buffer and that content is then split across as many fragments as > > necessary. > > > > Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com> > > --- > > I think this looks good (and is a long-overdue addition to the logging > functionality). > > One thought I have (and I'm kicking myself for not thinking of it > earlier) is that this is starting to get very similar to the "string > stream" functionality in lib/kunit/string-stream.{h,c}. Now, I > actually think this implementation is much more efficient (using > larger fragments, whereas the string stream uses variable-sized ones). > Particularly since there are a lot of cases where string streams are > created, converted to a string, and then logged, there's almost > certainly a bunch of redundant work being done here. > > My gut feeling is that we should stick with this as-is, and maybe try > to either work out some better integration between string streams and > logging (to avoid that extra string allocation) or find some way of > combining them. > > Regardless, this seems good as-is to me. There are some minor comments > below, but nothing disastrous. I'll let Rae have a look over the > various strscpy and strlcat calls, though, as while I did check them > carefully (and KASAN hasn't complained), it's always best to have as > many eyes on C string code as possible. :-) > Hello! I have tested and taken a look at this and it looks overall good to me. I think all of the string copying and concatenating is right. Other than David's comments below, especially whether we should do this with string-stream, I am pretty happy to accept this as is. Thanks! Rae > But in my eyes, this is > Reviewed-by: David Gow <davidgow@google.com> > > Cheers, > -- David > > > lib/kunit/test.c | 65 +++++++++++++++++++++++++++++++++++++++++++++--- > > 1 file changed, 61 insertions(+), 4 deletions(-) > > > > diff --git a/lib/kunit/test.c b/lib/kunit/test.c > > index dfe51bc2b387..28d0048d6171 100644 > > --- a/lib/kunit/test.c > > +++ b/lib/kunit/test.c > > @@ -140,25 +140,82 @@ static struct kunit_log_frag *kunit_log_extend(struct list_head *log) > > return frag; > > } > > > > +static void kunit_log_append_string(struct list_head *log, const char *src) > > +{ > > + struct kunit_log_frag *frag, *new_frag; > > + int log_len, bytes_left; > > + ssize_t written; > > + char *p; > > + > > + frag = list_last_entry(log, struct kunit_log_frag, list); > > + log_len = strlen(frag->buf); > > + bytes_left = sizeof(frag->buf) - log_len; > > + > > + written = strscpy(frag->buf + log_len, src, bytes_left); > > + if (written != -E2BIG) > > + goto newline; > > + > > + src += bytes_left - 1; > > + do { > > + new_frag = kunit_log_extend(log); > > + if (!new_frag) > > + goto newline; > > + > > + frag = new_frag; > > + written = strscpy(frag->buf, src, sizeof(frag->buf)); > > + src += sizeof(frag->buf) - 1; > > + } while (written == -E2BIG); > > + > > +newline: > > + if (written == -E2BIG) > > I think that this can only be true if kunit_log_extend() fails. If the > do/while loop ends naturally, then written != -E2BIG, as is the case > with the strscpy goto above. > > Do you think it's cleaner to move the 'written = strlen(frag->buf) > into the if (!new_frag) statement within the loop? > > > + written = strlen(frag->buf); > > + > > + p = &frag->buf[written - 1]; > > + if (*p != '\n') { > > + if (strlcat(frag->buf, "\n", sizeof(frag->buf)) >= sizeof(frag->buf)) { > > + frag = kunit_log_extend(log); > > + if (!frag) { > > A comment here could be useful. Something like "If we can't extend the > log to add a newline, truncate the last message". > > > + *p = '\n'; > > + return; > > + } > > + > > + frag->buf[0] = '\n'; > > + frag->buf[1] = '\0'; > > + } > > + } > > +} > > + > > /* Append formatted message to log, extending the log buffer if necessary. */ > > void kunit_log_append(struct list_head *log, const char *fmt, ...) > > { > > va_list args; > > struct kunit_log_frag *frag; > > int len, log_len, len_left; > > + char *tmp = NULL; > > > > if (!log) > > return; > > > > - frag = list_last_entry(log, struct kunit_log_frag, list); > > - log_len = strlen(frag->buf); > > - len_left = sizeof(frag->buf) - log_len - 1; > > - > > /* Evaluate length of line to add to log */ > > va_start(args, fmt); > > len = vsnprintf(NULL, 0, fmt, args) + 1; > > va_end(args); > > > > + if (len > sizeof(frag->buf) - 1) { > > + va_start(args, fmt); > > + tmp = kvasprintf(GFP_KERNEL, fmt, args); > > + va_end(args); > > + > > Should we handle the case where kvasprintf() fails here and drop the > log message? > > > > + kunit_log_append_string(log, tmp); > > + kfree(tmp); > > + > > + return; > > + } > > + > > + frag = list_last_entry(log, struct kunit_log_frag, list); > > + log_len = strlen(frag->buf); > > + len_left = sizeof(frag->buf) - log_len - 1; > > + > > if (len > len_left) { > > frag = kunit_log_extend(log); > > if (!frag) > > -- > > 2.30.2 > >
On Thu, 10 Aug 2023 at 23:09, Richard Fitzgerald <rf@opensource.cirrus.com> wrote: > > On 10/8/23 15:38, David Gow wrote: > > On Wed, 9 Aug 2023 at 23:54, Richard Fitzgerald > > <rf@opensource.cirrus.com> wrote: > >> > >> Add handling to kunit_log_append() for log messages that are longer than > >> a single buffer fragment. > >> > >> The initial implementation of fragmented buffers did not change the logic > >> of the original kunit_log_append(). A consequence was that it still had > >> the original assumption that a log line will fit into one buffer. > >> > >> This patch checks for log messages that are larger than one fragment > >> buffer. In that case, kvasprintf() is used to format it into a temporary > >> buffer and that content is then split across as many fragments as > >> necessary. > >> > >> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com> > >> --- > > > > I think this looks good (and is a long-overdue addition to the logging > > functionality). > > > > One thought I have (and I'm kicking myself for not thinking of it > > earlier) is that this is starting to get very similar to the "string > > stream" functionality in lib/kunit/string-stream.{h,c}. Now, I > > actually think this implementation is much more efficient (using > > larger fragments, whereas the string stream uses variable-sized ones). > > Particularly since there are a lot of cases where string streams are > > created, converted to a string, and then logged, there's almost > > certainly a bunch of redundant work being done here. > > > > My gut feeling is that we should stick with this as-is, and maybe try > > to either work out some better integration between string streams and > > logging (to avoid that extra string allocation) or find some way of > > combining them. > > > > I completely failed to notice string_stream. I could re-implement this > to use string_stream. I wonder whether appending newlines gets > a bit inefficient with the current string_stream implementation. > Could add newline support to string_stream and alloc one extra byte for > each fragment just in case we need to add a newline. > > The string_stream implementation would waste a lot a memory if you log > many short lines. My current code wastes memory if you log lots of lines > that don't fit in available space in the current fragment - though it's > simple to shuffle the formatted string backwards to fill up the previous > fragment (I just haven't done that yet). Yeah: I think your implementation here is overall better than the string_stream one. string_stream might handle concurrency a bit better, which would be nice to have as people start wanting to try multithreaded tests. I think the ideal solution is: - Update string_stream to basically use this implementation. - Update the logging code to then use this via the string_stream API (probably with some tweaks to handle newlines) - Optimize the string_stream append implementation to not create a temporary string, as string streams are written to logs often. (If you were prepared to allow string stream fragments to have variable lengths, and do some ownership shenanigans, this could even become O(1), though I suspect it's not worth the added complexity.) That being said, I don't think we'd need to land all of that at once. Even if we ported to the suboptimal string_stream API now (which would still gain us the extensible log and some concurrency support), and optimized string_stream later if it turned out to be tricky, that'd be fine. (I wouldn't want to hold this up if changing string_stream was regressing the other code which uses it, for example.) How does that sound? -- David
diff --git a/lib/kunit/test.c b/lib/kunit/test.c index dfe51bc2b387..28d0048d6171 100644 --- a/lib/kunit/test.c +++ b/lib/kunit/test.c @@ -140,25 +140,82 @@ static struct kunit_log_frag *kunit_log_extend(struct list_head *log) return frag; } +static void kunit_log_append_string(struct list_head *log, const char *src) +{ + struct kunit_log_frag *frag, *new_frag; + int log_len, bytes_left; + ssize_t written; + char *p; + + frag = list_last_entry(log, struct kunit_log_frag, list); + log_len = strlen(frag->buf); + bytes_left = sizeof(frag->buf) - log_len; + + written = strscpy(frag->buf + log_len, src, bytes_left); + if (written != -E2BIG) + goto newline; + + src += bytes_left - 1; + do { + new_frag = kunit_log_extend(log); + if (!new_frag) + goto newline; + + frag = new_frag; + written = strscpy(frag->buf, src, sizeof(frag->buf)); + src += sizeof(frag->buf) - 1; + } while (written == -E2BIG); + +newline: + if (written == -E2BIG) + written = strlen(frag->buf); + + p = &frag->buf[written - 1]; + if (*p != '\n') { + if (strlcat(frag->buf, "\n", sizeof(frag->buf)) >= sizeof(frag->buf)) { + frag = kunit_log_extend(log); + if (!frag) { + *p = '\n'; + return; + } + + frag->buf[0] = '\n'; + frag->buf[1] = '\0'; + } + } +} + /* Append formatted message to log, extending the log buffer if necessary. */ void kunit_log_append(struct list_head *log, const char *fmt, ...) { va_list args; struct kunit_log_frag *frag; int len, log_len, len_left; + char *tmp = NULL; if (!log) return; - frag = list_last_entry(log, struct kunit_log_frag, list); - log_len = strlen(frag->buf); - len_left = sizeof(frag->buf) - log_len - 1; - /* Evaluate length of line to add to log */ va_start(args, fmt); len = vsnprintf(NULL, 0, fmt, args) + 1; va_end(args); + if (len > sizeof(frag->buf) - 1) { + va_start(args, fmt); + tmp = kvasprintf(GFP_KERNEL, fmt, args); + va_end(args); + + kunit_log_append_string(log, tmp); + kfree(tmp); + + return; + } + + frag = list_last_entry(log, struct kunit_log_frag, list); + log_len = strlen(frag->buf); + len_left = sizeof(frag->buf) - log_len - 1; + if (len > len_left) { frag = kunit_log_extend(log); if (!frag)
Add handling to kunit_log_append() for log messages that are longer than a single buffer fragment. The initial implementation of fragmented buffers did not change the logic of the original kunit_log_append(). A consequence was that it still had the original assumption that a log line will fit into one buffer. This patch checks for log messages that are larger than one fragment buffer. In that case, kvasprintf() is used to format it into a temporary buffer and that content is then split across as many fragments as necessary. Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com> --- lib/kunit/test.c | 65 +++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 61 insertions(+), 4 deletions(-)