diff mbox series

[v2,1/6] kunit: Replace fixed-size log with dynamically-extending buffer

Message ID 20230808123529.4725-2-rf@opensource.cirrus.com (mailing list archive)
State New
Delegated to: Brendan Higgins
Headers show
Series kunit: Add dynamically-extending log | expand

Commit Message

Richard Fitzgerald Aug. 8, 2023, 12:35 p.m. UTC
Re-implement the log buffer as a list of buffer fragments that can
be extended as the size of the log info grows.

When using parameterization the test case can run many times and create
a large amount of log. It's not really practical to keep increasing the
size of the fixed buffer every time a test needs more space. And a big
fixed buffer wastes memory.

The original char *log pointer is replaced by a pointer to a list of
struct kunit_log_frag, each containing a fixed-size buffer.

kunit_log_append() now attempts to append to the last kunit_log_frag in
the list. If there isn't enough space it will append a new kunit_log_frag
to the list. This simple implementation does not attempt to completely
fill the buffer in every kunit_log_frag.

The 'log' member of kunit_suite, kunit_test_case and kunit_suite must be a
pointer because the API of kunit_log() requires that is the same type in
all  three structs. As kunit.log is a pointer to the 'log' of the current
kunit_case, it must be a pointer in the other two structs.

The existing kunit-test.c log tests have been updated to build against the
new fragmented log implementation.

Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
---
 include/kunit/test.h   | 25 +++++++++++-----
 lib/kunit/debugfs.c    | 65 ++++++++++++++++++++++++++++++++++--------
 lib/kunit/kunit-test.c | 29 +++++++++++++------
 lib/kunit/test.c       | 63 ++++++++++++++++++++++++++++------------
 4 files changed, 136 insertions(+), 46 deletions(-)

Comments

David Gow Aug. 9, 2023, 12:11 p.m. UTC | #1
On Tue, 8 Aug 2023 at 20:35, Richard Fitzgerald
<rf@opensource.cirrus.com> wrote:
>
> Re-implement the log buffer as a list of buffer fragments that can
> be extended as the size of the log info grows.
>
> When using parameterization the test case can run many times and create
> a large amount of log. It's not really practical to keep increasing the
> size of the fixed buffer every time a test needs more space. And a big
> fixed buffer wastes memory.
>
> The original char *log pointer is replaced by a pointer to a list of
> struct kunit_log_frag, each containing a fixed-size buffer.
>
> kunit_log_append() now attempts to append to the last kunit_log_frag in
> the list. If there isn't enough space it will append a new kunit_log_frag
> to the list. This simple implementation does not attempt to completely
> fill the buffer in every kunit_log_frag.
>
> The 'log' member of kunit_suite, kunit_test_case and kunit_suite must be a
> pointer because the API of kunit_log() requires that is the same type in
> all  three structs. As kunit.log is a pointer to the 'log' of the current
> kunit_case, it must be a pointer in the other two structs.
>
> The existing kunit-test.c log tests have been updated to build against the
> new fragmented log implementation.
>
> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
> ---

Looks good to me.

A few small notes inline below, mostly around the possibility of
either embedding the list_head in the kunit_case struct directly
(rather than using a pointer), or of pointing directly to the first
fragment, rather than a separately-allocated struct list_head. Neither
are showstoppers, though (and if it increases complexity at all, it's
possibly premature optimization).

Otherwise, some test nitpicks and the fact that this will need a
trivial rebase due to the module filtering stuff landing in
kselftest/kunit.

Reviewed-by: David Gow <davidgow@google.com>

The other patches in the series pass the initial sniff test: I'll try
to get a more thorough review done in the next day or two.

Cheers,
-- David

>  include/kunit/test.h   | 25 +++++++++++-----
>  lib/kunit/debugfs.c    | 65 ++++++++++++++++++++++++++++++++++--------
>  lib/kunit/kunit-test.c | 29 +++++++++++++------
>  lib/kunit/test.c       | 63 ++++++++++++++++++++++++++++------------
>  4 files changed, 136 insertions(+), 46 deletions(-)
>
> diff --git a/include/kunit/test.h b/include/kunit/test.h
> index 011e0d6bb506..ef8e09aafe1b 100644
> --- a/include/kunit/test.h
> +++ b/include/kunit/test.h
> @@ -33,8 +33,8 @@ DECLARE_STATIC_KEY_FALSE(kunit_running);
>
>  struct kunit;
>
> -/* Size of log associated with test. */
> -#define KUNIT_LOG_SIZE 2048
> +/* Size of log buffer fragments. */
> +#define KUNIT_LOG_FRAGMENT_SIZE (256 - sizeof(struct list_head))
>
>  /* Maximum size of parameter description string. */
>  #define KUNIT_PARAM_DESC_SIZE 128
> @@ -85,6 +85,11 @@ struct kunit_attributes {
>         enum kunit_speed speed;
>  };
>
> +struct kunit_log_frag {
> +       struct list_head list;
> +       char buf[KUNIT_LOG_FRAGMENT_SIZE];
> +};
> +
>  /**
>   * struct kunit_case - represents an individual test case.
>   *
> @@ -132,7 +137,7 @@ struct kunit_case {
>         /* private: internal use only. */
>         enum kunit_status status;
>         char *module_name;
> -       char *log;
> +       struct list_head *log;

I wonder if this has to be a pointer? Would it make more sense to
embed the struct list_head (or possibly a whole struct
kunit_log_fragment if we weren't worried about kernel image size, see
below) here, to avoid an extra allocation and a bunch of extra
indirect memory accesses.

Even if we still want to pass a pointer to a struct list_head around,
we could just take the address of this one, rather than allocating it
separately. We'd have to copy the whole struct list_head around,
rather than just the pointer, and it'd increase the size of struct
kunit_case and similar, but struct list_head is just two pointers, so
it shouldn't be drastic enough to matter.

Not a problem either way: I doubt this would be a performance or
memory bottleneck, so if it's simpler to keep it as a pointer I don't
mind, but if it's an easy enough change, it may be worth it.

>  };
>
>  static inline char *kunit_status_to_ok_not_ok(enum kunit_status status)
> @@ -252,7 +257,7 @@ struct kunit_suite {
>         /* private: internal use only */
>         char status_comment[KUNIT_STATUS_COMMENT_SIZE];
>         struct dentry *debugfs;
> -       char *log;
> +       struct list_head *log;

As above, should this be a pointer?

>         int suite_init_err;
>  };
>
> @@ -272,7 +277,7 @@ struct kunit {
>
>         /* private: internal use only. */
>         const char *name; /* Read only after initialization! */
> -       char *log; /* Points at case log after initialization */
> +       struct list_head *log; /* Points at case log after initialization */

I could imagine this either being a pointer to &(case.log), or a copy
of the list_head which is then copied back into the case structure if
we went with a less pointer-y implementation.

>         struct kunit_try_catch try_catch;
>         /* param_value is the current parameter value for a test case. */
>         const void *param_value;
> @@ -304,7 +309,7 @@ static inline void kunit_set_failure(struct kunit *test)
>
>  bool kunit_enabled(void);
>
> -void kunit_init_test(struct kunit *test, const char *name, char *log);
> +void kunit_init_test(struct kunit *test, const char *name, struct list_head *log);
>
>  int kunit_run_tests(struct kunit_suite *suite);
>
> @@ -317,6 +322,12 @@ int __kunit_test_suites_init(struct kunit_suite * const * const suites, int num_
>
>  void __kunit_test_suites_exit(struct kunit_suite **suites, int num_suites);
>
> +static inline void kunit_init_log_frag(struct kunit_log_frag *frag)
> +{
> +       INIT_LIST_HEAD(&frag->list);
> +       frag->buf[0] = '\0';
> +}
> +

There's now a (trivial) conflict between this and the latest
kselftest/kunit branch (with the module filtering patches). If you're
doing a v3, could you rebase?

>  #if IS_BUILTIN(CONFIG_KUNIT)
>  int kunit_run_all_tests(void);
>  #else
> @@ -451,7 +462,7 @@ static inline void *kunit_kcalloc(struct kunit *test, size_t n, size_t size, gfp
>
>  void kunit_cleanup(struct kunit *test);
>
> -void __printf(2, 3) kunit_log_append(char *log, const char *fmt, ...);
> +void __printf(2, 3) kunit_log_append(struct list_head *log, const char *fmt, ...);
>
>  /**
>   * kunit_mark_skipped() - Marks @test_or_suite as skipped
> diff --git a/lib/kunit/debugfs.c b/lib/kunit/debugfs.c
> index 22c5c496a68f..a26b6d31bd2f 100644
> --- a/lib/kunit/debugfs.c
> +++ b/lib/kunit/debugfs.c
> @@ -5,6 +5,7 @@
>   */
>
>  #include <linux/debugfs.h>
> +#include <linux/list.h>
>  #include <linux/module.h>
>
>  #include <kunit/test.h>
> @@ -37,14 +38,15 @@ void kunit_debugfs_init(void)
>                 debugfs_rootdir = debugfs_create_dir(KUNIT_DEBUGFS_ROOT, NULL);
>  }
>
> -static void debugfs_print_result(struct seq_file *seq,
> -                                struct kunit_suite *suite,
> -                                struct kunit_case *test_case)
> +static void debugfs_print_log(struct seq_file *seq, const struct list_head *log)
>  {
> -       if (!test_case || !test_case->log)
> +       struct kunit_log_frag *frag;
> +
> +       if (!log)
>                 return;
>
> -       seq_printf(seq, "%s", test_case->log);
> +       list_for_each_entry(frag, log, list)
> +               seq_puts(seq, frag->buf);
>  }
>
>  /*
> @@ -69,10 +71,9 @@ static int debugfs_print_results(struct seq_file *seq, void *v)
>         seq_printf(seq, KUNIT_SUBTEST_INDENT "1..%zd\n", kunit_suite_num_test_cases(suite));
>
>         kunit_suite_for_each_test_case(suite, test_case)
> -               debugfs_print_result(seq, suite, test_case);
> +               debugfs_print_log(seq, test_case->log);
>
> -       if (suite->log)
> -               seq_printf(seq, "%s", suite->log);
> +       debugfs_print_log(seq, suite->log);
>
>         seq_printf(seq, "%s %d %s\n",
>                    kunit_status_to_ok_not_ok(success), 1, suite->name);
> @@ -100,14 +101,53 @@ static const struct file_operations debugfs_results_fops = {
>         .release = debugfs_release,
>  };
>
> +static struct list_head *kunit_debugfs_alloc_log(void)
> +{
> +       struct list_head *log;
> +       struct kunit_log_frag *frag;
> +
> +       log = kzalloc(sizeof(*log), GFP_KERNEL);
> +       if (!log)
> +               return NULL;
> +
> +       INIT_LIST_HEAD(log);
> +
> +       frag = kmalloc(sizeof(*frag), GFP_KERNEL);

If we're always allocating at least one fragment, would it make sense
to embed a while kunit_log_frag in the test struct, rather than just a
list_head (so the first fragment doesn't need allocating separately)?

Of course, that could bloat the kunit_case / kunit_suite structs too
much (and therefore the .kunit_test_suites section). But maybe even a
pointer to a kunit_log_frag would work.

Probably not worth the extra complexity, but it's a thought...

> +       if (!frag) {
> +               kfree(log);
> +               return NULL;
> +       }
> +
> +       kunit_init_log_frag(frag);
> +       list_add_tail(&frag->list, log);
> +
> +       return log;
> +}
> +
> +static void kunit_debugfs_free_log(struct list_head *log)
> +{
> +       struct kunit_log_frag *frag, *n;
> +
> +       if (!log)
> +               return;
> +
> +       list_for_each_entry_safe(frag, n, log, list) {
> +               list_del(&frag->list);
> +               kfree(frag);
> +       }
> +
> +       kfree(log);
> +}
> +
>  void kunit_debugfs_create_suite(struct kunit_suite *suite)
>  {
>         struct kunit_case *test_case;
>
>         /* Allocate logs before creating debugfs representation. */
> -       suite->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
> +       suite->log = kunit_debugfs_alloc_log();
> +
>         kunit_suite_for_each_test_case(suite, test_case)
> -               test_case->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
> +               test_case->log = kunit_debugfs_alloc_log();
>
>         suite->debugfs = debugfs_create_dir(suite->name, debugfs_rootdir);
>
> @@ -121,7 +161,8 @@ void kunit_debugfs_destroy_suite(struct kunit_suite *suite)
>         struct kunit_case *test_case;
>
>         debugfs_remove_recursive(suite->debugfs);
> -       kfree(suite->log);
> +       kunit_debugfs_free_log(suite->log);
> +
>         kunit_suite_for_each_test_case(suite, test_case)
> -               kfree(test_case->log);
> +               kunit_debugfs_free_log(test_case->log);
>  }
> diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
> index 83d8e90ca7a2..54dc011c8980 100644
> --- a/lib/kunit/kunit-test.c
> +++ b/lib/kunit/kunit-test.c
> @@ -533,9 +533,16 @@ static struct kunit_suite kunit_resource_test_suite = {
>  static void kunit_log_test(struct kunit *test)
>  {
>         struct kunit_suite suite;
> +       struct kunit_log_frag *frag;
>
> -       suite.log = kunit_kzalloc(test, KUNIT_LOG_SIZE, GFP_KERNEL);
> +       suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
>         KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
> +       INIT_LIST_HEAD(suite.log);
> +       frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
> +       KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
> +       kunit_init_log_frag(frag);
> +       KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
> +       list_add_tail(&frag->list, suite.log);
>
>         kunit_log(KERN_INFO, test, "put this in log.");
>         kunit_log(KERN_INFO, test, "this too.");
> @@ -543,14 +550,17 @@ static void kunit_log_test(struct kunit *test)
>         kunit_log(KERN_INFO, &suite, "along with this.");
>
>  #ifdef CONFIG_KUNIT_DEBUGFS
> +       frag = list_first_entry(test->log, struct kunit_log_frag, list);
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(test->log, "put this in log."));
> +                                    strstr(frag->buf, "put this in log."));
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(test->log, "this too."));
> +                                    strstr(frag->buf, "this too."));
> +
> +       frag = list_first_entry(suite.log, struct kunit_log_frag, list);
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(suite.log, "add to suite log."));
> +                                    strstr(frag->buf, "add to suite log."));
>         KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
> -                                    strstr(suite.log, "along with this."));
> +                                    strstr(frag->buf, "along with this."));
>  #else
>         KUNIT_EXPECT_NULL(test, test->log);
>  #endif
> @@ -558,11 +568,14 @@ static void kunit_log_test(struct kunit *test)
>
>  static void kunit_log_newline_test(struct kunit *test)
>  {
> +       struct kunit_log_frag *frag;
> +
>         kunit_info(test, "Add newline\n");
>         if (test->log) {
> -               KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(test->log, "Add newline\n"),
> -                       "Missing log line, full log:\n%s", test->log);
> -               KUNIT_EXPECT_NULL(test, strstr(test->log, "Add newline\n\n"));
> +               frag = list_first_entry(test->log, struct kunit_log_frag, list);
> +               KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
> +                       "Missing log line, full log:\n%s", frag->buf);

I'm not super thrilled that this only operates on the first fragment.
Could we at least note that this is not the "full log" in the
assertion message here, and maybe also assert that the log hasn't
grown to a second fragment?

> +               KUNIT_EXPECT_NULL(test, strstr(frag->buf, "Add newline\n\n"));
>         } else {
>                 kunit_skip(test, "only useful when debugfs is enabled");
>         }
> diff --git a/lib/kunit/test.c b/lib/kunit/test.c
> index cb9797fa6303..bdb361741214 100644
> --- a/lib/kunit/test.c
> +++ b/lib/kunit/test.c
> @@ -11,6 +11,7 @@
>  #include <kunit/test-bug.h>
>  #include <kunit/attributes.h>
>  #include <linux/kernel.h>
> +#include <linux/list.h>
>  #include <linux/module.h>
>  #include <linux/moduleparam.h>
>  #include <linux/panic.h>
> @@ -114,46 +115,66 @@ static void kunit_print_test_stats(struct kunit *test,
>   * already present.
>   * @log: The log to add the newline to.
>   */
> -static void kunit_log_newline(char *log)
> +static void kunit_log_newline(struct kunit_log_frag *frag)
>  {
>         int log_len, len_left;
>
> -       log_len = strlen(log);
> -       len_left = KUNIT_LOG_SIZE - log_len - 1;
> +       log_len = strlen(frag->buf);
> +       len_left = sizeof(frag->buf) - log_len - 1;
>
> -       if (log_len > 0 && log[log_len - 1] != '\n')
> -               strncat(log, "\n", len_left);
> +       if (log_len > 0 && frag->buf[log_len - 1] != '\n')
> +               strncat(frag->buf, "\n", len_left);
>  }
>
> -/*
> - * Append formatted message to log, size of which is limited to
> - * KUNIT_LOG_SIZE bytes (including null terminating byte).
> - */
> -void kunit_log_append(char *log, const char *fmt, ...)
> +static struct kunit_log_frag *kunit_log_extend(struct list_head *log)
> +{
> +       struct kunit_log_frag *frag;
> +
> +       frag = kmalloc(sizeof(*frag), GFP_KERNEL);
> +       if (!frag)
> +               return NULL;
> +
> +       kunit_init_log_frag(frag);
> +       list_add_tail(&frag->list, log);
> +
> +       return frag;
> +}
> +
> +/* 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;
>
>         if (!log)
>                 return;
>
> -       log_len = strlen(log);
> -       len_left = KUNIT_LOG_SIZE - log_len - 1;
> -       if (len_left <= 0)
> -               return;
> +       frag = list_last_entry(log, struct kunit_log_frag, list);
> +       log_len = strlen(frag->buf);

I was going to wonder whether or not we should cache the length of the
current fragment somewhere, but thinking about it, it's probably not
worth it given we're only measuring a single fragment, and it's capped
at 256 bytes.


> +       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 > len_left) {
> +               frag = kunit_log_extend(log);
> +               if (!frag)
> +                       return;
> +
> +               len_left = sizeof(frag->buf) - 1;
> +               log_len = 0;
> +       }
> +
>         /* Print formatted line to the log */
>         va_start(args, fmt);
> -       vsnprintf(log + log_len, min(len, len_left), fmt, args);
> +       vsnprintf(frag->buf + log_len, min(len, len_left), fmt, args);
>         va_end(args);
>
>         /* Add newline to end of log if not already present. */
> -       kunit_log_newline(log);
> +       kunit_log_newline(frag);
>  }
>  EXPORT_SYMBOL_GPL(kunit_log_append);
>
> @@ -359,14 +380,18 @@ void __kunit_do_failed_assertion(struct kunit *test,
>  }
>  EXPORT_SYMBOL_GPL(__kunit_do_failed_assertion);
>
> -void kunit_init_test(struct kunit *test, const char *name, char *log)
> +void kunit_init_test(struct kunit *test, const char *name, struct list_head *log)
>  {
>         spin_lock_init(&test->lock);
>         INIT_LIST_HEAD(&test->resources);
>         test->name = name;
>         test->log = log;
> -       if (test->log)
> -               test->log[0] = '\0';
> +       if (test->log) {
> +               struct kunit_log_frag *frag = list_first_entry(test->log,
> +                                                              struct kunit_log_frag,
> +                                                              list);
> +               frag->buf[0] = '\0';
> +       }
>         test->status = KUNIT_SUCCESS;
>         test->status_comment[0] = '\0';
>  }
> --
> 2.30.2
>
Richard Fitzgerald Aug. 9, 2023, 2:37 p.m. UTC | #2
On 9/8/23 13:11, David Gow wrote:
> On Tue, 8 Aug 2023 at 20:35, Richard Fitzgerald
> <rf@opensource.cirrus.com> wrote:
>>
>> Re-implement the log buffer as a list of buffer fragments that can
>> be extended as the size of the log info grows.
>>
>> When using parameterization the test case can run many times and create
>> a large amount of log. It's not really practical to keep increasing the
>> size of the fixed buffer every time a test needs more space. And a big
>> fixed buffer wastes memory.
>>
>> The original char *log pointer is replaced by a pointer to a list of
>> struct kunit_log_frag, each containing a fixed-size buffer.
>>
>> kunit_log_append() now attempts to append to the last kunit_log_frag in
>> the list. If there isn't enough space it will append a new kunit_log_frag
>> to the list. This simple implementation does not attempt to completely
>> fill the buffer in every kunit_log_frag.
>>
>> The 'log' member of kunit_suite, kunit_test_case and kunit_suite must be a
>> pointer because the API of kunit_log() requires that is the same type in
>> all  three structs. As kunit.log is a pointer to the 'log' of the current
>> kunit_case, it must be a pointer in the other two structs.
>>
>> The existing kunit-test.c log tests have been updated to build against the
>> new fragmented log implementation.
>>
>> Signed-off-by: Richard Fitzgerald <rf@opensource.cirrus.com>
>> ---
> 
> Looks good to me.
> 
> A few small notes inline below, mostly around the possibility of
> either embedding the list_head in the kunit_case struct directly
> (rather than using a pointer), or of pointing directly to the first
> fragment, rather than a separately-allocated struct list_head. Neither
> are showstoppers, though (and if it increases complexity at all, it's
> possibly premature optimization).
>

I did start out trying to use the first fragment as the list head.
Trouble with this is that the functions in list.h expect to have a
dummy list_head node that is only the head, but not an actual list
member. It's possible to workaround this but the shenanigans involved is
likely to trip someone up later so reverted to doing the list the way
the API intended.

For the pointers, I did consider embedding the list_head instead of
using a pointer. But then the struct kunit can't refer to the
kunit_case list, it can only take it over. There can only be one list
head because the ->prev and ->next pointers of the first and last
members in the list can only point to one head.

After playing around with it I decided that it wasn't worth trying to
avoid the pointers. At least... it wasn't worth spending a lot of time
trying to avoid them for an initial implementation.

Maybe some magic with typeof() in the kunit_log() would let us use
different types for the members of kunit_suite, kunit_case, kunit?
Then the list_head can be directly embedded in the first two but a
pointer in kunit?

> Otherwise, some test nitpicks and the fact that this will need a
> trivial rebase due to the module filtering stuff landing in
> kselftest/kunit.
> 
> Reviewed-by: David Gow <davidgow@google.com>
> 

...

>>   static void kunit_log_newline_test(struct kunit *test)
>>   {
>> +       struct kunit_log_frag *frag;
>> +
>>          kunit_info(test, "Add newline\n");
>>          if (test->log) {
>> -               KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(test->log, "Add newline\n"),
>> -                       "Missing log line, full log:\n%s", test->log);
>> -               KUNIT_EXPECT_NULL(test, strstr(test->log, "Add newline\n\n"));
>> +               frag = list_first_entry(test->log, struct kunit_log_frag, list);
>> +               KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
>> +                       "Missing log line, full log:\n%s", frag->buf);
> 
> I'm not super thrilled that this only operates on the first fragment.
> Could we at least note that this is not the "full log" in the
> assertion message here, and maybe also assert that the log hasn't
> grown to a second fragment?
> 

The only aim in this first patch is to make sure that kunit-test.c still
builds. I've added extra newline test cases in later patches.

...

> 
> I was going to wonder whether or not we should cache the length of the
> current fragment somewhere, but thinking about it, it's probably not
> worth it given we're only measuring a single fragment, and it's capped
> at 256 bytes.
> 
Yes, I had the same thought but decided to leave it as something that
can be done later. But as you say it's doubtful whether it's worth the
extra storage space when the buffer fragments are small. On x86_64
simply adding a length member could add 8 bytes per fragment (because of
rounding). If the size of the fragment buffer is capped at 256 we could
use single byte for the length and hope the compiler doesn't insert
padding between a char and a char[] array.

Take a look at what happens when you log a message to the kernel log and
by comparison this kunit logging is super-lightweight.

(I did look at whether we could re-use the existing kernel log
implementation but decided it was too heavily hardcoded to how the
kernel log works.)
diff mbox series

Patch

diff --git a/include/kunit/test.h b/include/kunit/test.h
index 011e0d6bb506..ef8e09aafe1b 100644
--- a/include/kunit/test.h
+++ b/include/kunit/test.h
@@ -33,8 +33,8 @@  DECLARE_STATIC_KEY_FALSE(kunit_running);
 
 struct kunit;
 
-/* Size of log associated with test. */
-#define KUNIT_LOG_SIZE 2048
+/* Size of log buffer fragments. */
+#define KUNIT_LOG_FRAGMENT_SIZE (256 - sizeof(struct list_head))
 
 /* Maximum size of parameter description string. */
 #define KUNIT_PARAM_DESC_SIZE 128
@@ -85,6 +85,11 @@  struct kunit_attributes {
 	enum kunit_speed speed;
 };
 
+struct kunit_log_frag {
+	struct list_head list;
+	char buf[KUNIT_LOG_FRAGMENT_SIZE];
+};
+
 /**
  * struct kunit_case - represents an individual test case.
  *
@@ -132,7 +137,7 @@  struct kunit_case {
 	/* private: internal use only. */
 	enum kunit_status status;
 	char *module_name;
-	char *log;
+	struct list_head *log;
 };
 
 static inline char *kunit_status_to_ok_not_ok(enum kunit_status status)
@@ -252,7 +257,7 @@  struct kunit_suite {
 	/* private: internal use only */
 	char status_comment[KUNIT_STATUS_COMMENT_SIZE];
 	struct dentry *debugfs;
-	char *log;
+	struct list_head *log;
 	int suite_init_err;
 };
 
@@ -272,7 +277,7 @@  struct kunit {
 
 	/* private: internal use only. */
 	const char *name; /* Read only after initialization! */
-	char *log; /* Points at case log after initialization */
+	struct list_head *log; /* Points at case log after initialization */
 	struct kunit_try_catch try_catch;
 	/* param_value is the current parameter value for a test case. */
 	const void *param_value;
@@ -304,7 +309,7 @@  static inline void kunit_set_failure(struct kunit *test)
 
 bool kunit_enabled(void);
 
-void kunit_init_test(struct kunit *test, const char *name, char *log);
+void kunit_init_test(struct kunit *test, const char *name, struct list_head *log);
 
 int kunit_run_tests(struct kunit_suite *suite);
 
@@ -317,6 +322,12 @@  int __kunit_test_suites_init(struct kunit_suite * const * const suites, int num_
 
 void __kunit_test_suites_exit(struct kunit_suite **suites, int num_suites);
 
+static inline void kunit_init_log_frag(struct kunit_log_frag *frag)
+{
+	INIT_LIST_HEAD(&frag->list);
+	frag->buf[0] = '\0';
+}
+
 #if IS_BUILTIN(CONFIG_KUNIT)
 int kunit_run_all_tests(void);
 #else
@@ -451,7 +462,7 @@  static inline void *kunit_kcalloc(struct kunit *test, size_t n, size_t size, gfp
 
 void kunit_cleanup(struct kunit *test);
 
-void __printf(2, 3) kunit_log_append(char *log, const char *fmt, ...);
+void __printf(2, 3) kunit_log_append(struct list_head *log, const char *fmt, ...);
 
 /**
  * kunit_mark_skipped() - Marks @test_or_suite as skipped
diff --git a/lib/kunit/debugfs.c b/lib/kunit/debugfs.c
index 22c5c496a68f..a26b6d31bd2f 100644
--- a/lib/kunit/debugfs.c
+++ b/lib/kunit/debugfs.c
@@ -5,6 +5,7 @@ 
  */
 
 #include <linux/debugfs.h>
+#include <linux/list.h>
 #include <linux/module.h>
 
 #include <kunit/test.h>
@@ -37,14 +38,15 @@  void kunit_debugfs_init(void)
 		debugfs_rootdir = debugfs_create_dir(KUNIT_DEBUGFS_ROOT, NULL);
 }
 
-static void debugfs_print_result(struct seq_file *seq,
-				 struct kunit_suite *suite,
-				 struct kunit_case *test_case)
+static void debugfs_print_log(struct seq_file *seq, const struct list_head *log)
 {
-	if (!test_case || !test_case->log)
+	struct kunit_log_frag *frag;
+
+	if (!log)
 		return;
 
-	seq_printf(seq, "%s", test_case->log);
+	list_for_each_entry(frag, log, list)
+		seq_puts(seq, frag->buf);
 }
 
 /*
@@ -69,10 +71,9 @@  static int debugfs_print_results(struct seq_file *seq, void *v)
 	seq_printf(seq, KUNIT_SUBTEST_INDENT "1..%zd\n", kunit_suite_num_test_cases(suite));
 
 	kunit_suite_for_each_test_case(suite, test_case)
-		debugfs_print_result(seq, suite, test_case);
+		debugfs_print_log(seq, test_case->log);
 
-	if (suite->log)
-		seq_printf(seq, "%s", suite->log);
+	debugfs_print_log(seq, suite->log);
 
 	seq_printf(seq, "%s %d %s\n",
 		   kunit_status_to_ok_not_ok(success), 1, suite->name);
@@ -100,14 +101,53 @@  static const struct file_operations debugfs_results_fops = {
 	.release = debugfs_release,
 };
 
+static struct list_head *kunit_debugfs_alloc_log(void)
+{
+	struct list_head *log;
+	struct kunit_log_frag *frag;
+
+	log = kzalloc(sizeof(*log), GFP_KERNEL);
+	if (!log)
+		return NULL;
+
+	INIT_LIST_HEAD(log);
+
+	frag = kmalloc(sizeof(*frag), GFP_KERNEL);
+	if (!frag) {
+		kfree(log);
+		return NULL;
+	}
+
+	kunit_init_log_frag(frag);
+	list_add_tail(&frag->list, log);
+
+	return log;
+}
+
+static void kunit_debugfs_free_log(struct list_head *log)
+{
+	struct kunit_log_frag *frag, *n;
+
+	if (!log)
+		return;
+
+	list_for_each_entry_safe(frag, n, log, list) {
+		list_del(&frag->list);
+		kfree(frag);
+	}
+
+	kfree(log);
+}
+
 void kunit_debugfs_create_suite(struct kunit_suite *suite)
 {
 	struct kunit_case *test_case;
 
 	/* Allocate logs before creating debugfs representation. */
-	suite->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
+	suite->log = kunit_debugfs_alloc_log();
+
 	kunit_suite_for_each_test_case(suite, test_case)
-		test_case->log = kzalloc(KUNIT_LOG_SIZE, GFP_KERNEL);
+		test_case->log = kunit_debugfs_alloc_log();
 
 	suite->debugfs = debugfs_create_dir(suite->name, debugfs_rootdir);
 
@@ -121,7 +161,8 @@  void kunit_debugfs_destroy_suite(struct kunit_suite *suite)
 	struct kunit_case *test_case;
 
 	debugfs_remove_recursive(suite->debugfs);
-	kfree(suite->log);
+	kunit_debugfs_free_log(suite->log);
+
 	kunit_suite_for_each_test_case(suite, test_case)
-		kfree(test_case->log);
+		kunit_debugfs_free_log(test_case->log);
 }
diff --git a/lib/kunit/kunit-test.c b/lib/kunit/kunit-test.c
index 83d8e90ca7a2..54dc011c8980 100644
--- a/lib/kunit/kunit-test.c
+++ b/lib/kunit/kunit-test.c
@@ -533,9 +533,16 @@  static struct kunit_suite kunit_resource_test_suite = {
 static void kunit_log_test(struct kunit *test)
 {
 	struct kunit_suite suite;
+	struct kunit_log_frag *frag;
 
-	suite.log = kunit_kzalloc(test, KUNIT_LOG_SIZE, GFP_KERNEL);
+	suite.log = kunit_kzalloc(test, sizeof(*suite.log), GFP_KERNEL);
 	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, suite.log);
+	INIT_LIST_HEAD(suite.log);
+	frag = kunit_kmalloc(test, sizeof(*frag), GFP_KERNEL);
+	KUNIT_ASSERT_NOT_ERR_OR_NULL(test, frag);
+	kunit_init_log_frag(frag);
+	KUNIT_EXPECT_EQ(test, frag->buf[0], '\0');
+	list_add_tail(&frag->list, suite.log);
 
 	kunit_log(KERN_INFO, test, "put this in log.");
 	kunit_log(KERN_INFO, test, "this too.");
@@ -543,14 +550,17 @@  static void kunit_log_test(struct kunit *test)
 	kunit_log(KERN_INFO, &suite, "along with this.");
 
 #ifdef CONFIG_KUNIT_DEBUGFS
+	frag = list_first_entry(test->log, struct kunit_log_frag, list);
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(test->log, "put this in log."));
+				     strstr(frag->buf, "put this in log."));
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(test->log, "this too."));
+				     strstr(frag->buf, "this too."));
+
+	frag = list_first_entry(suite.log, struct kunit_log_frag, list);
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(suite.log, "add to suite log."));
+				     strstr(frag->buf, "add to suite log."));
 	KUNIT_EXPECT_NOT_ERR_OR_NULL(test,
-				     strstr(suite.log, "along with this."));
+				     strstr(frag->buf, "along with this."));
 #else
 	KUNIT_EXPECT_NULL(test, test->log);
 #endif
@@ -558,11 +568,14 @@  static void kunit_log_test(struct kunit *test)
 
 static void kunit_log_newline_test(struct kunit *test)
 {
+	struct kunit_log_frag *frag;
+
 	kunit_info(test, "Add newline\n");
 	if (test->log) {
-		KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(test->log, "Add newline\n"),
-			"Missing log line, full log:\n%s", test->log);
-		KUNIT_EXPECT_NULL(test, strstr(test->log, "Add newline\n\n"));
+		frag = list_first_entry(test->log, struct kunit_log_frag, list);
+		KUNIT_ASSERT_NOT_NULL_MSG(test, strstr(frag->buf, "Add newline\n"),
+			"Missing log line, full log:\n%s", frag->buf);
+		KUNIT_EXPECT_NULL(test, strstr(frag->buf, "Add newline\n\n"));
 	} else {
 		kunit_skip(test, "only useful when debugfs is enabled");
 	}
diff --git a/lib/kunit/test.c b/lib/kunit/test.c
index cb9797fa6303..bdb361741214 100644
--- a/lib/kunit/test.c
+++ b/lib/kunit/test.c
@@ -11,6 +11,7 @@ 
 #include <kunit/test-bug.h>
 #include <kunit/attributes.h>
 #include <linux/kernel.h>
+#include <linux/list.h>
 #include <linux/module.h>
 #include <linux/moduleparam.h>
 #include <linux/panic.h>
@@ -114,46 +115,66 @@  static void kunit_print_test_stats(struct kunit *test,
  * already present.
  * @log: The log to add the newline to.
  */
-static void kunit_log_newline(char *log)
+static void kunit_log_newline(struct kunit_log_frag *frag)
 {
 	int log_len, len_left;
 
-	log_len = strlen(log);
-	len_left = KUNIT_LOG_SIZE - log_len - 1;
+	log_len = strlen(frag->buf);
+	len_left = sizeof(frag->buf) - log_len - 1;
 
-	if (log_len > 0 && log[log_len - 1] != '\n')
-		strncat(log, "\n", len_left);
+	if (log_len > 0 && frag->buf[log_len - 1] != '\n')
+		strncat(frag->buf, "\n", len_left);
 }
 
-/*
- * Append formatted message to log, size of which is limited to
- * KUNIT_LOG_SIZE bytes (including null terminating byte).
- */
-void kunit_log_append(char *log, const char *fmt, ...)
+static struct kunit_log_frag *kunit_log_extend(struct list_head *log)
+{
+	struct kunit_log_frag *frag;
+
+	frag = kmalloc(sizeof(*frag), GFP_KERNEL);
+	if (!frag)
+		return NULL;
+
+	kunit_init_log_frag(frag);
+	list_add_tail(&frag->list, log);
+
+	return frag;
+}
+
+/* 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;
 
 	if (!log)
 		return;
 
-	log_len = strlen(log);
-	len_left = KUNIT_LOG_SIZE - log_len - 1;
-	if (len_left <= 0)
-		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 > len_left) {
+		frag = kunit_log_extend(log);
+		if (!frag)
+			return;
+
+		len_left = sizeof(frag->buf) - 1;
+		log_len = 0;
+	}
+
 	/* Print formatted line to the log */
 	va_start(args, fmt);
-	vsnprintf(log + log_len, min(len, len_left), fmt, args);
+	vsnprintf(frag->buf + log_len, min(len, len_left), fmt, args);
 	va_end(args);
 
 	/* Add newline to end of log if not already present. */
-	kunit_log_newline(log);
+	kunit_log_newline(frag);
 }
 EXPORT_SYMBOL_GPL(kunit_log_append);
 
@@ -359,14 +380,18 @@  void __kunit_do_failed_assertion(struct kunit *test,
 }
 EXPORT_SYMBOL_GPL(__kunit_do_failed_assertion);
 
-void kunit_init_test(struct kunit *test, const char *name, char *log)
+void kunit_init_test(struct kunit *test, const char *name, struct list_head *log)
 {
 	spin_lock_init(&test->lock);
 	INIT_LIST_HEAD(&test->resources);
 	test->name = name;
 	test->log = log;
-	if (test->log)
-		test->log[0] = '\0';
+	if (test->log) {
+		struct kunit_log_frag *frag = list_first_entry(test->log,
+							       struct kunit_log_frag,
+							       list);
+		frag->buf[0] = '\0';
+	}
 	test->status = KUNIT_SUCCESS;
 	test->status_comment[0] = '\0';
 }