[PATCH i-g-t v2 0/4] Add support for KUnit tests

[Isabella Basso]

This patch series was first developed as part of the LKCamp hackathon
that happened last year[1], mainly focusing on refactoring DRM tests to
use KUnit.

KUnit[2][3] is a unified test framework that provides helper tools,
simplifying their development and execution. Using an x86-64 machine
it's possible to run tests in the host's kernel natively using user-mode
Linux[4] (aka UML), which simplifies usage in a wide variety of
scenarios, including integration to CI.

As the tool's adoption widens into graphics testing territory, I and
LKCamp members figured it would be important to support it in IGT, as
it's a core tool for GPU drivers maintainers.

I have then added KUnit support into IGT mainly following the KTAP
specs, and it can be tested using patch 4/4 in this series together with
a DRM selftests patch series available at [5].

Changes since v1:
- Major rework of parsing function structure:
- It is not longer recursive
- Adapt kselftests functions and structs to be used with KUnit
- Switch DRM selftests to KUnit parsing as they're updated in the kernel
- Replace AMD KUnit tests by DRM selftests

[1]: https://groups.google.com/g/kunit-dev/c/YqFR1q2uZvk/m/IbvItSfHBAAJ
[2]: https://kunit.dev
[3]: https://docs.kernel.org/dev-tools/kunit/index.html
[4]: http://user-mode-linux.sourceforge.net
[5]: https://lore.kernel.org/all/20220708203052.23...@usp.br/

Isabella Basso (4):
lib/igt_kmod: rename kselftest functions to ktest
lib/igt_kmod.c: check if module is builtin before attempting to unload
it
lib/igt_kmod: add compatibility for KUnit
tests: DRM selftests: switch to KUnit

lib/igt_kmod.c | 315 +++++++++++++++++++++++++++++++++++++++++--
lib/igt_kmod.h | 14 +-
tests/drm_buddy.c | 7 +-
tests/drm_mm.c | 7 +-
tests/kms_selftest.c | 12 +-
5 files changed, 329 insertions(+), 26 deletions(-)

--
2.37.2

[Isabella Basso]

This aims at making IGT's structure more general to different kernel
testing frameworks such as KUnit, as they use a lot of the same
functionality.

Signed-off-by: Isabella Basso <isab...@riseup.net>
---
lib/igt_kmod.c | 22 +++++++++++-----------
lib/igt_kmod.h | 12 ++++++------
2 files changed, 17 insertions(+), 17 deletions(-)

diff --git a/lib/igt_kmod.c b/lib/igt_kmod.c
index bcf7dfeb..bb6cb7bb 100644
--- a/lib/igt_kmod.c
+++ b/lib/igt_kmod.c
@@ -718,8 +718,8 @@ static int open_parameters(const char *module_name)
return open(path, O_RDONLY);
}

-int igt_kselftest_init(struct igt_kselftest *tst,
- const char *module_name)
+int igt_ktest_init(struct igt_ktest *tst,
+ const char *module_name)
{
int err;

@@ -738,7 +738,7 @@ int igt_kselftest_init(struct igt_kselftest *tst,
return 0;
}

-int igt_kselftest_begin(struct igt_kselftest *tst)
+int igt_ktest_begin(struct igt_ktest *tst)
{
int err;

@@ -753,7 +753,7 @@ int igt_kselftest_begin(struct igt_kselftest *tst)
return 0;
}

-int igt_kselftest_execute(struct igt_kselftest *tst,
+int igt_kselftest_execute(struct igt_ktest *tst,
struct igt_kselftest_list *tl,
const char *options,
const char *result)
@@ -791,13 +791,13 @@ int igt_kselftest_execute(struct igt_kselftest *tst,
return err;
}

-void igt_kselftest_end(struct igt_kselftest *tst)
+void igt_ktest_end(struct igt_ktest *tst)
{
kmod_module_remove_module(tst->kmod, KMOD_REMOVE_FORCE);
close(tst->kmsg);
}

-void igt_kselftest_fini(struct igt_kselftest *tst)
+void igt_ktest_fini(struct igt_ktest *tst)
{
free(tst->module_name);
kmod_module_unref(tst->kmod);
@@ -820,15 +820,15 @@ void igt_kselftests(const char *module_name,
const char *result,
const char *filter)
{
- struct igt_kselftest tst;
+ struct igt_ktest tst;
IGT_LIST_HEAD(tests);
struct igt_kselftest_list *tl, *tn;

- if (igt_kselftest_init(&tst, module_name) != 0)
+ if (igt_ktest_init(&tst, module_name) != 0)
return;

igt_fixture
- igt_require(igt_kselftest_begin(&tst) == 0);
+ igt_require(igt_ktest_begin(&tst) == 0);

igt_kselftest_get_tests(tst.kmod, filter, &tests);
igt_subtest_with_dynamic(filter ?: "all") {
@@ -847,9 +847,9 @@ void igt_kselftests(const char *module_name,
}

igt_fixture {
- igt_kselftest_end(&tst);
+ igt_ktest_end(&tst);
igt_require(!igt_list_empty(&tests));
}

- igt_kselftest_fini(&tst);
+ igt_ktest_fini(&tst);
}
diff --git a/lib/igt_kmod.h b/lib/igt_kmod.h
index f98dd29f..ceb10cd0 100644
--- a/lib/igt_kmod.h
+++ b/lib/igt_kmod.h
@@ -50,7 +50,7 @@ void igt_kselftests(const char *module_name,
const char *result_option,
const char *filter);

-struct igt_kselftest {
+struct igt_ktest {
struct kmod_module *kmod;
char *module_name;
int kmsg;
@@ -63,19 +63,19 @@ struct igt_kselftest_list {
char param[];
};

-int igt_kselftest_init(struct igt_kselftest *tst,
+int igt_ktest_init(struct igt_ktest *tst,
const char *module_name);
-int igt_kselftest_begin(struct igt_kselftest *tst);
+int igt_ktest_begin(struct igt_ktest *tst);

void igt_kselftest_get_tests(struct kmod_module *kmod,
const char *filter,
struct igt_list_head *tests);
-int igt_kselftest_execute(struct igt_kselftest *tst,
+int igt_kselftest_execute(struct igt_ktest *tst,
struct igt_kselftest_list *tl,
const char *module_options,
const char *result);

-void igt_kselftest_end(struct igt_kselftest *tst);
-void igt_kselftest_fini(struct igt_kselftest *tst);
+void igt_ktest_end(struct igt_ktest *tst);
+void igt_ktest_fini(struct igt_ktest *tst);

#endif /* IGT_KMOD_H */
--
2.37.2

[Isabella Basso]

This change makes `igt_module_unload_r` safer as it checks whether the
module can be unloaded before attempting it.

Signed-off-by: Isabella Basso <isab...@riseup.net>
---

lib/igt_kmod.c | 3 +++
1 file changed, 3 insertions(+)

diff --git a/lib/igt_kmod.c b/lib/igt_kmod.c
index bb6cb7bb..97cac7f5 100644
--- a/lib/igt_kmod.c
+++ b/lib/igt_kmod.c
@@ -256,6 +256,9 @@ static int igt_kmod_unload_r(struct kmod_module *kmod, unsigned int flags)
struct kmod_list *holders, *pos;
int err = 0;

+ if (kmod_module_get_initstate(kmod) == KMOD_MODULE_BUILTIN)
+ return err;
+
holders = kmod_module_get_holders(kmod);
kmod_list_foreach(pos, holders) {
struct kmod_module *it = kmod_module_get_module(pos);
--
2.37.2

[Isabella Basso]

This adds functions for both executing the tests as well as parsing (K)TAP
kmsg output, as per the KTAP spec [1].

[1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html

Signed-off-by: Isabella Basso <isab...@riseup.net>
---

lib/igt_kmod.c | 290 +++++++++++++++++++++++++++++++++++++++++++++++++
lib/igt_kmod.h | 2 +
2 files changed, 292 insertions(+)

diff --git a/lib/igt_kmod.c b/lib/igt_kmod.c
index 97cac7f5..93cdfcc5 100644
--- a/lib/igt_kmod.c
+++ b/lib/igt_kmod.c
@@ -25,6 +25,7 @@
#include <signal.h>
#include <errno.h>
#include <sys/utsname.h>
+#include <limits.h>

#include "igt_aux.h"
#include "igt_core.h"
@@ -32,6 +33,8 @@
#include "igt_sysfs.h"
#include "igt_taints.h"

+#define BUF_LEN 4096
+
/**
* SECTION:igt_kmod
* @short_description: Wrappers around libkmod for module loading/unloading
@@ -713,6 +716,293 @@ void igt_kselftest_get_tests(struct kmod_module *kmod,
kmod_module_info_free_list(pre);
}

+/**
+ * lookup_value:
+ * @haystack: the string to search in
+ * @needle: the string to search for
+ *
+ * Returns: the value of the needle in the haystack, or -1 if not found.
+ */
+static long lookup_value(const char *haystack, const char *needle)
+{
+ const char *needle_rptr;
+ char *needle_end;
+ long num;
+
+ needle_rptr = strcasestr(haystack, needle);
+
+ if (needle_rptr == NULL)
+ return -1;
+
+ /* skip search string and whitespaces after it */
+ needle_rptr += strlen(needle);
+
+ num = strtol(needle_rptr, &needle_end, 10);
+
+ if (needle_rptr == needle_end)
+ return -1;
+
+ if (num == LONG_MIN || num == LONG_MAX)
+ return 0;
+
+ return num > 0 ? num : 0;
+}
+
+static int find_next_tap_subtest(char *record, char *test_name,
+ bool is_subtest)
+{
+ const char *name_lookup_str,
+ *lend, *version_rptr, *name_rptr;
+ long test_count;
+
+ name_lookup_str = "test: ";
+
+ version_rptr = strcasestr(record, "TAP version ");
+ name_rptr = strcasestr(record, name_lookup_str);
+
+ /*
+ * total test count will almost always appear as 0..N at the beginning
+ * of a run, so we use it as indication of a run
+ */
+ test_count = lookup_value(record, "..");
+
+ /* no count found, so this is probably not starting a (sub)test */
+ if (test_count < 0) {
+ if (name_rptr != NULL) {
+ if (test_name[0] == '\0')
+ strncpy(test_name,
+ name_rptr + strlen(name_lookup_str),
+ BUF_LEN);
+ else if (strcmp(test_name, name_rptr + strlen(name_lookup_str)) == 0)
+ return 0;
+ else
+ test_name[0] = '\0';
+
+ }
+ return -1;
+ }
+
+ /*
+ * "(K)TAP version XX" should be the first line on all (sub)tests as per
+ * https://www.kernel.org/doc/html/latest/dev-tools/ktap.html#version-lines
+ * but actually isn't, as it currently depends on whoever writes the
+ * test to print this info
+ */
+ if (version_rptr == NULL)
+ igt_info("Missing test version string\n");
+
+ if (name_rptr == NULL) {
+ /* we have to keep track of the name string, as it might be
+ * contained in a line read previously */
+ if (test_name[0] == '\0') {
+ igt_info("Missing test name string\n");
+
+ if (is_subtest)
+ igt_info("Running %ld subtests...\n", test_count);
+ else
+ igt_info("Running %ld tests...\n", test_count);
+ } else {
+ lend = strchrnul(test_name, '\n');
+
+ if (*lend == '\0') {
+ if (is_subtest)
+ igt_info("Executing %ld subtests in: %s\n",
+ test_count, test_name);
+ else
+ igt_info("Executing %ld tests in: %s\n",
+ test_count, test_name);
+ return test_count;
+ }
+
+ if (is_subtest)
+ igt_info("Executing %ld subtests in: %.*s\n",
+ test_count, (int)(lend - test_name),
+ test_name);
+ else
+ igt_info("Executing %ld tests in: %.*s\n",
+ test_count, (int)(lend - test_name),
+ test_name);
+ test_name[0] = '\0';
+ }
+ } else {
+ name_rptr += strlen(name_lookup_str);
+ lend = strchrnul(name_rptr, '\n');
+ /*
+ * as the test count comes after the test name we need not check
+ * for a long line again
+ */
+ if (is_subtest)
+ igt_info("Executing %ld subtests in: %.*s\n",
+ test_count, (int)(lend - name_rptr),
+ name_rptr);
+ else
+ igt_info("Executing %ld tests in: %.*s\n",
+ test_count, (int)(lend - name_rptr),
+ name_rptr);
+ }
+
+ return test_count;
+}
+
+static void parse_kmsg_for_tap(const char *lstart, char *lend,
+ int *sublevel, bool *failed_tests)
+{
+ const char *nok_rptr, *comment_start, *value_parse_start;
+
+ nok_rptr = strstr(lstart, "not ok ");
+ if (nok_rptr != NULL) {
+ igt_warn("kmsg> %.*s\n",
+ (int)(lend - lstart), lstart);
+ *failed_tests = true;
+ return;
+ }
+
+ comment_start = strchrnul(lstart, '#');
+
+ /* check if we're still in a subtest */
+ if (*comment_start != '\0') {
+ comment_start++;
+ value_parse_start = comment_start;
+
+ if (lookup_value(value_parse_start, "fail: ") > 0) {
+ igt_warn("kmsg> %.*s\n",
+ (int)(lend - comment_start), comment_start);
+ *failed_tests = true;
+ (*sublevel)--;
+ return;
+ }
+ }
+
+ igt_info("kmsg> %.*s\n",
+ (int)(lend - lstart), lstart);
+}
+
+static void igt_kunit_subtests(int fd, char *record,
+ int *sublevel, bool *failed_tests)
+{
+ char test_name[BUF_LEN + 1], *lend;
+
+ lend = NULL;
+ test_name[0] = '\0';
+ test_name[BUF_LEN] = '\0';
+
+ while (*sublevel >= 0) {
+ const char *lstart;
+ ssize_t r;
+
+ if (lend != NULL && *lend != '\0')
+ lseek(fd, (int) (lend - record), SEEK_CUR);
+
+ r = read(fd, record, BUF_LEN);
+
+ if (r <= 0) {
+ switch (errno) {
+ case EINTR:
+ continue;
+ case EPIPE:
+ igt_warn("kmsg truncated: too many messages. \
+ You may want to increase log_buf_len \
+ in your boot options\n");
+ continue;
+ case !EAGAIN:
+ igt_warn("kmsg truncated: unknown error (%m)\n");
+ *sublevel = -1;
+ default:
+ break;
+ }
+ break;
+ }
+
+ lend = strchrnul(record, '\n');
+
+ /* in case line > 4096 */
+ if (*lend == '\0')
+ continue;
+
+ if (find_next_tap_subtest(record, test_name, *sublevel > 0) != -1)
+ (*sublevel)++;
+
+ if (*sublevel > 0) {
+ lstart = strchrnul(record, ';');
+
+ if (*lstart == '\0') {
+ igt_warn("kmsg truncated: output malformed (%m)\n");
+ igt_fail(IGT_EXIT_FAILURE);
+ }
+
+ lstart++;
+ while (isspace(*lstart))
+ lstart++;
+
+ parse_kmsg_for_tap(lstart, lend, sublevel, failed_tests);
+ }
+ }
+
+ if (*failed_tests || *sublevel < 0)
+ igt_fail(IGT_EXIT_FAILURE);
+ else
+ igt_success();
+}
+
+/**
+ * igt_kunit:
+ * @module_name: the name of the module
+ * @opts: options to load the module
+ *
+ * Loads the kunit module, parses its dmesg output, then unloads it
+ */
+void igt_kunit(const char *module_name, const char *opts)
+{
+ struct igt_ktest tst;
+ char record[BUF_LEN + 1];
+ bool failed_tests = false;
+ int sublevel = 0;
+
+ record[BUF_LEN] = '\0';
+
+ /* get normalized module name */
+ if (igt_ktest_init(&tst, module_name) != 0) {
+ igt_warn("Unable to initialize ktest for %s\n", module_name);
+ return;
+ }
+
+ if (igt_ktest_begin(&tst) != 0) {
+ igt_warn("Unable to begin ktest for %s\n", module_name);
+
+ igt_ktest_fini(&tst);
+ return;
+ }
+
+ if (tst.kmsg < 0) {
+ igt_warn("Could not open /dev/kmsg");
+ goto unload;
+ }
+
+ if (lseek(tst.kmsg, 0, SEEK_END)) {
+ igt_warn("Could not seek the end of /dev/kmsg");
+ goto unload;
+ }
+
+ /* The kunit module is required for running any kunit tests */
+ if (igt_kmod_load("kunit", NULL) != 0) {
+ igt_warn("Unable to load kunit module\n");
+ goto unload;
+ }
+
+ if (igt_kmod_load(module_name, opts) != 0) {
+ igt_warn("Unable to load %s module\n", module_name);
+ goto unload;
+ }
+
+ igt_kunit_subtests(tst.kmsg, record, &sublevel, &failed_tests);
+unload:
+ igt_kmod_unload("kunit", 0);
+
+ igt_ktest_end(&tst);
+
+ igt_ktest_fini(&tst);
+}
+

static int open_parameters(const char *module_name)

{
char path[256];
diff --git a/lib/igt_kmod.h b/lib/igt_kmod.h
index ceb10cd0..737143c1 100644
--- a/lib/igt_kmod.h
+++ b/lib/igt_kmod.h
@@ -45,6 +45,8 @@ int __igt_i915_driver_unload(char **whom);
int igt_amdgpu_driver_load(const char *opts);
int igt_amdgpu_driver_unload(void);

+void igt_kunit(const char *module_name, const char *opts);
+
void igt_kselftests(const char *module_name,
const char *module_options,
const char *result_option,
--
2.37.2

[Isabella Basso]

As the DRM selftests are now using KUnit [1], update IGT tests as well.

[1] - https://lore.kernel.org/all/20220708203052.23...@usp.br/

Signed-off-by: Isabella Basso <isab...@riseup.net>
---

tests/drm_buddy.c | 7 ++++---
tests/drm_mm.c | 7 ++++---
tests/kms_selftest.c | 12 +++++++++---
3 files changed, 17 insertions(+), 9 deletions(-)

diff --git a/tests/drm_buddy.c b/tests/drm_buddy.c
index 06876e0c..74c06dce 100644
--- a/tests/drm_buddy.c
+++ b/tests/drm_buddy.c
@@ -6,9 +6,10 @@
#include "igt.h"
#include "igt_kmod.h"

-IGT_TEST_DESCRIPTION("Basic sanity check of DRM's buddy allocator (struct drm_buddy)");
+IGT_TEST_DESCRIPTION("Basic sanity check of DRM's buddy allocator (struct \
+ drm_buddy) using KUnit");

-igt_main
+igt_simple_main
{
- igt_kselftests("test-drm_buddy", NULL, NULL, NULL);
+ igt_kunit("drm_buddy_test", NULL);
}
diff --git a/tests/drm_mm.c b/tests/drm_mm.c
index 2052b115..75fc6682 100644
--- a/tests/drm_mm.c
+++ b/tests/drm_mm.c
@@ -24,9 +24,10 @@
#include "igt.h"
#include "igt_kmod.h"

-IGT_TEST_DESCRIPTION("Basic sanity check of DRM's range manager (struct drm_mm)");
+IGT_TEST_DESCRIPTION("Basic sanity check of DRM's range manager (struct drm_mm)\
+ using KUnit");

-igt_main
+igt_simple_main
{
- igt_kselftests("test-drm_mm", NULL, NULL, NULL);
+ igt_kunit("drm_mm_test", NULL);
}
diff --git a/tests/kms_selftest.c b/tests/kms_selftest.c
index abc4bfe9..bbf24c2b 100644
--- a/tests/kms_selftest.c
+++ b/tests/kms_selftest.c
@@ -24,9 +24,15 @@
#include "igt.h"
#include "igt_kmod.h"

-IGT_TEST_DESCRIPTION("Basic sanity check of KMS selftests.");
+IGT_TEST_DESCRIPTION("Basic sanity check of KMS selftests using KUnit");

-igt_main
+igt_simple_main
{
- igt_kselftests("test-drm_modeset", NULL, NULL, NULL);
+ igt_kunit("drm_cmdline_parser_test", NULL);
+ igt_kunit("drm_damage_helper_test", NULL);
+ igt_kunit("drm_dp_mst_helper_test", NULL);
+ igt_kunit("drm_format_helper_test", NULL);
+ igt_kunit("drm_format_test", NULL);
+ igt_kunit("drm_framebuffer_test", NULL);
+ igt_kunit("drm_plane_helper_test", NULL);
}
--
2.37.2

[David Gow]

On Mon, Aug 29, 2022 at 8:10 AM Isabella Basso <isab...@riseup.net> wrote:
>
> This adds functions for both executing the tests as well as parsing (K)TAP
> kmsg output, as per the KTAP spec [1].
>
> [1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html
>
> Signed-off-by: Isabella Basso <isab...@riseup.net>
> ---

Thanks very much for sending these patches out again.

Alas, I don't have a particularly useful igt setup to test this
properly, but I've left a couple of notes from trying it on my laptop
here.

FYI: we're really trying to fix cases of "missing version lines",
largely by making the kunit_test_suites() macro work in more
circumstances.

So while it may be worth still handling the case where this is
missing, I don't think there are any tests in the latest versions of
the kernel which should have this missing.

Do you want to _require_ KUnit be built as a module, rather than built-in here?

Equally, does this need to mark a failure (or at least "SKIPPED")
rather than success, in the case it fails.

> +
> + if (igt_kmod_load(module_name, opts) != 0) {
> + igt_warn("Unable to load %s module\n", module_name);
> + goto unload;
> + }

As above, should this record a failure, or skip?

> +
> + igt_kunit_subtests(tst.kmsg, record, &sublevel, &failed_tests);
> +unload:
> + igt_kmod_unload("kunit", 0);

Do you want to unconditionally unload the KUnit module here? It's safe
(maybe even safer) to leave it loaded between runs of KUnit tests.

Equally, how would you handle the case where KUnit is already loaded?

> +
> + igt_ktest_end(&tst);
> +
> + igt_ktest_fini(&tst);
> +}
> +
> static int open_parameters(const char *module_name)
> {
> char path[256];
> diff --git a/lib/igt_kmod.h b/lib/igt_kmod.h
> index ceb10cd0..737143c1 100644
> --- a/lib/igt_kmod.h
> +++ b/lib/igt_kmod.h
> @@ -45,6 +45,8 @@ int __igt_i915_driver_unload(char **whom);
> int igt_amdgpu_driver_load(const char *opts);
> int igt_amdgpu_driver_unload(void);
>
> +void igt_kunit(const char *module_name, const char *opts);
> +
> void igt_kselftests(const char *module_name,
> const char *module_options,
> const char *result_option,
> --
> 2.37.2
>

Regardless, thanks very much. Hopefully I'll get a chance to play with
igt a bit more and actually get the tests running. :-)

Cheers,
-- David

[Janusz Krzysztofik]

Hi Isabella,

On Monday, 29 August 2022 02:09:16 CEST Isabella Basso wrote:
> This patch series was first developed as part of the LKCamp hackathon
> that happened last year[1], mainly focusing on refactoring DRM tests to
> use KUnit.
>
> KUnit[2][3] is a unified test framework that provides helper tools,
> simplifying their development and execution. Using an x86-64 machine
> it's possible to run tests in the host's kernel natively using user-mode
> Linux[4] (aka UML), which simplifies usage in a wide variety of
> scenarios, including integration to CI.
>
> As the tool's adoption widens into graphics testing territory, I and
> LKCamp members figured it would be important to support it in IGT, as
> it's a core tool for GPU drivers maintainers.
>
> I have then added KUnit support into IGT mainly following the KTAP
> specs, and it can be tested using patch 4/4 in this series together with
> a DRM selftests patch series available at [5].

CI pre-merge results indicate that your new versions of tests were not able to
load kunit module, then didn't actually execute any kunit tests, but returned
SUCCESS. That's probably not what we expect from IGT tests.

https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_7698/shard-rkl-4/igt@drm_buddy.html
https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_7698/shard-rkl-1/igt@drm_mm.html
https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_7698/shard-rkl-5/igt@kms_selftest.html

Thanks,
Janusz

[Janusz Krzysztofik]

On Monday, 29 August 2022 02:09:17 CEST Isabella Basso wrote:
> This aims at making IGT's structure more general to different kernel
> testing frameworks such as KUnit, as they use a lot of the same
> functionality.
>
> Signed-off-by: Isabella Basso <isab...@riseup.net>

LGTM

Reviewed-by: Janusz Krzysztofik <janusz.kr...@linux.intel.com>

[Janusz Krzysztofik]

On Monday, 29 August 2022 02:09:18 CEST Isabella Basso wrote:
> This change makes `igt_module_unload_r` safer as it checks whether the

s/igt_module_unload_r/igt_kmod_unload_r/

> module can be unloaded before attempting it.
>
> Signed-off-by: Isabella Basso <isab...@riseup.net>
> ---
> lib/igt_kmod.c | 3 +++
> 1 file changed, 3 insertions(+)
>
> diff --git a/lib/igt_kmod.c b/lib/igt_kmod.c
> index bb6cb7bb..97cac7f5 100644
> --- a/lib/igt_kmod.c
> +++ b/lib/igt_kmod.c
> @@ -256,6 +256,9 @@ static int igt_kmod_unload_r(struct kmod_module *kmod, unsigned int flags)
> struct kmod_list *holders, *pos;
> int err = 0;
>
> + if (kmod_module_get_initstate(kmod) == KMOD_MODULE_BUILTIN)
> + return err;

NIT: I think that return 0; would be more clear. Anyway,

Acked-by: Janusz Krzysztofik <janusz.kr...@linux.intel.com>

[Janusz Krzysztofik]

Hi Isabella,

This function looks like nothing but a KTAP parser. It doesn't perform any
operations required for execution of kunit tests. Shouldn't we better name it
like igt_ktap_parser or something like that? Besides, I would move that
parser code to a separate source file.

> + igt_warn("kmsg truncated: unknown error (%m)\n");something

If the intention here is to display this warning only in other cases but
EAGAIN error then that won't work as intended.

> + *sublevel = -1;

Shouldn't *sublevel be also set to -1 in all cases but EINTR and EPIPE,
whether EAGAIN or anything else?

Other than that, please use /* fallthrough */ marking if you intentionally
omit break;

> + default:
> + break;
> + }
> + break;
> + }
> +
> + lend = strchrnul(record, '\n');
> +
> + /* in case line > 4096 */
> + if (*lend == '\0')
> + continue;

That means we are free to ignore initial fragments of lines exceeding 4096
characters, but still will be looking at trailing fragments of those lines.
This approach seems sub-optimal to me. Wouldn't it be more convenient if we
used line buffered I/O instead of read()?

Since igt_ktest_begin() as is calls igt_require() then it may be used only
from inside an igt_fixture or igt_subtest block. If the intention is to call
igt_kunit() from an igt_subtest block, unlike igt_kselftest() which has
igt_fixture and igt_subtest blocks placed in its body, please document that.

What's the point of passing that many temporary variable pointers to
igt_kunit_subtests() if we are not interested here in content of any of those
variables after the function returns? That function could perfectly use its
own local variables for storing that data.

Besides, my comment about not using igt_require() outside of igt_fixture or
igt_subtest blocks also applies to igt_fail() and igt_success() called from
igt_kunit_subtests().

Anyway, related to my comment about naming that function a parser, I think the
best approach would be for that parser to return a generic set of results from
kunit execution, then we could feed that data into an IGT specific handler
that would convert them to IGT results (SUCCESS, FAIL, or SKIP) as if returned
by a set of IGT dynamic subtests.

Thanks,
Janusz

[Isabella Basso]

Hi, David

> Am 01/09/2022 um 3:37 AM schrieb 'David Gow' via KUnit Development <kuni...@googlegroups.com>:
>
> On Mon, Aug 29, 2022 at 8:10 AM Isabella Basso <isab...@riseup.net> wrote:
>>
>> This adds functions for both executing the tests as well as parsing (K)TAP
>> kmsg output, as per the KTAP spec [1].
>>
>> [1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html
>>
>> Signed-off-by: Isabella Basso <isab...@riseup.net>
>> ---
>
> Thanks very much for sending these patches out again.
>
> Alas, I don't have a particularly useful igt setup to test this
> properly, but I've left a couple of notes from trying it on my laptop
> here.

Thanks for the review, it’s much appreciated! If you have the time I’ve left a
note at the bottom with a very simple way to run the tests, but I can also
provide you with a pastebin of the results if you prefer.

I’m not sure if I totally get how these work. Every time I run a KUnit test I
get something like this: https://pastebin.com/7Ff31PMC

As you can see it has been loaded as a module, just like we intend to do it
from IGT, and I see no version lines whatsoever. Am I doing something wrong?

This line is a little misleading because, for our purposes, only the thing to
be tested has to be built as a module, but we can use this function for both
validating a built-in module as well as modprobe-ing it if it's „standalone" (I
tested both cases as well). I’ll change the comment and the warning in v3
to clarify this.

The actual problem would be to unload something that’s built-in, so that’s why
I added a check in the unload function in the previous patch.

> Equally, does this need to mark a failure (or at least "SKIPPED")
> rather than success, in the case it fails.

That’s a good point, will change in v3.

>> +
>> + if (igt_kmod_load(module_name, opts) != 0) {
>> + igt_warn("Unable to load %s module\n", module_name);
>> + goto unload;
>> + }
>
> As above, should this record a failure, or skip?

Ack.

>> +
>> + igt_kunit_subtests(tst.kmsg, record, &sublevel, &failed_tests);
>> +unload:
>> + igt_kmod_unload("kunit", 0);
>
> Do you want to unconditionally unload the KUnit module here? It's safe
> (maybe even safer) to leave it loaded between runs of KUnit tests.

That’s a great point. The user should be safe using KUnit as built-in in that
case, but I’ll remove this line as it is unnecessary.

> Equally, how would you handle the case where KUnit is already loaded?

That’s not a problem as pointed out above, kmod handles that without trouble.

>> +
>> + igt_ktest_end(&tst);
>> +
>> + igt_ktest_fini(&tst);
>> +}
>> +
>> static int open_parameters(const char *module_name)
>> {
>> char path[256];
>> diff --git a/lib/igt_kmod.h b/lib/igt_kmod.h
>> index ceb10cd0..737143c1 100644
>> --- a/lib/igt_kmod.h
>> +++ b/lib/igt_kmod.h
>> @@ -45,6 +45,8 @@ int __igt_i915_driver_unload(char **whom);
>> int igt_amdgpu_driver_load(const char *opts);
>> int igt_amdgpu_driver_unload(void);
>>
>> +void igt_kunit(const char *module_name, const char *opts);
>> +
>> void igt_kselftests(const char *module_name,
>> const char *module_options,
>> const char *result_option,
>> --
>> 2.37.2
>>
>
> Regardless, thanks very much. Hopefully I'll get a chance to play with
> igt a bit more and actually get the tests running. :-)

That shouldn’t be too difficult, when you compile IGT as per the docs you can
just run e.g. `sudo ./build/tests/drm_buddy` and that should do it :).

Cheers,
--
Isabella Basso

>
> Cheers,
> -- David

[Isabella Basso]

Hi, Janusz,

That sounds like a good idea to me, I might take some extra time before v3 to
do that, though. I’ll also look into your other suggestions carefully.

Thanks a lot for the review!

Cheers,
--
Isabella Basso

[Daniel Latypov]

On Mon, Sep 19, 2022 at 1:43 PM Isabella Basso <isab...@riseup.net> wrote:
> >> + * "(K)TAP version XX" should be the first line on all (sub)tests as per
> >> + * https://www.kernel.org/doc/html/latest/dev-tools/ktap.html#version-lines
> >> + * but actually isn't, as it currently depends on whoever writes the
> >> + * test to print this info
> >
> > FYI: we're really trying to fix cases of "missing version lines",
> > largely by making the kunit_test_suites() macro work in more
> > circumstances.
> >
> > So while it may be worth still handling the case where this is
> > missing, I don't think there are any tests in the latest versions of
> > the kernel which should have this missing.
>
> I’m not sure if I totally get how these work. Every time I run a KUnit test I
> get something like this: https://pastebin.com/7Ff31PMC
>
> As you can see it has been loaded as a module, just like we intend to do it
> from IGT, and I see no version lines whatsoever. Am I doing something wrong?

You're doing everything right.

The problem is we only print the version line for the *built-in* tests.
It never gets printed for tests in loadable modules.

Some more details below, if interested.
Specifically, it happens in
https://elixir.bootlin.com/linux/latest/C/ident/kunit_print_tap_header

What David is referring to is we had tests that weren't in modules,
but didn't use the normal built-in code path. Those were also missing
TAP version lines.
But KUnit needs to do better here in the case of modules.

The goal was that you'd be able to parse the result of module based
tests by something like
$ cat /sys/kernel/debug/kunit/*/results | ./tools/testing/kunit/kunit.py parse
but this doesn't work because of the lack of a version line.

If we add it to each module's test results, then we'll need to update
the parse to allow multiple verison lines, I think.

Daniel

[Petri Latvala]

On Sun, Aug 28, 2022 at 09:09:20PM -0300, Isabella Basso wrote:
> As the DRM selftests are now using KUnit [1], update IGT tests as well.
>
> [1] - https://lore.kernel.org/all/20220708203052.23...@usp.br/
>
> Signed-off-by: Isabella Basso <isab...@riseup.net>
> ---
> tests/drm_buddy.c | 7 ++++---
> tests/drm_mm.c | 7 ++++---
> tests/kms_selftest.c | 12 +++++++++---
> 3 files changed, 17 insertions(+), 9 deletions(-)
>
> diff --git a/tests/drm_buddy.c b/tests/drm_buddy.c
> index 06876e0c..74c06dce 100644
> --- a/tests/drm_buddy.c
> +++ b/tests/drm_buddy.c
> @@ -6,9 +6,10 @@
> #include "igt.h"
> #include "igt_kmod.h"
>
> -IGT_TEST_DESCRIPTION("Basic sanity check of DRM's buddy allocator (struct drm_buddy)");
> +IGT_TEST_DESCRIPTION("Basic sanity check of DRM's buddy allocator (struct \
> + drm_buddy) using KUnit");
>
> -igt_main
> +igt_simple_main
> {
> - igt_kselftests("test-drm_buddy", NULL, NULL, NULL);
> + igt_kunit("drm_buddy_test", NULL);
> }

With kselftests we had the ability to only run a specified set of
tests, and with or without selection, we had sub-results for each
through dynamic subtests. Does kunit have that possibility? I mean I
know kunit itself does but what about igt_kunit()?

Orthogonal to that question, drm_mm and test-drm_modeset are _now_
using kunit but in LTS kernels they're not, and we'd like to be able
to keep testing those. That means having both launchers here and just
letting the "incorrect" one produce a 'skip'.


--
Petri Latvala

[Mauro Carvalho Chehab]

That doesn't seem to be the case, at least when the tests are loaded
as module.

I'm working on adding more KUnit tests. At least here, TAP version
doesn't appear before the tests (I'm using drm-tip + my KUnit tests):

$ dmesg|grep TAP
[ 7.597592] TAP version 14
$ sudo lcov -z && sudo modprobe test-i915-mock && sudo IGT_KERNEL_TREE=~/linux ~/igt/scripts/code_cov_capture mock_selftest && sudo rmmod test-i915-mock
Auto-detecting gcov kernel support.
Found upstream gcov kernel support at /sys/kernel/debug/gcov
Resetting kernel execution counters
Done.
[3734.23] Code coverage wrote to mock_selftest.info
$ sudo ./tools/testing/kunit/kunit.py parse /var/log/dmesg
[12:15:50] ============================================================
[12:15:50] [ERROR] Test: main: 0 tests run!
[12:15:50] ============================================================
[12:15:50] Testing complete. Ran 0 tests: errors: 1

In order for kunit.py KTAP parser to work, I have to cheat by doing:

$ (dmesg|grep "TAP version"; dmesg|grep -A9999 intel_i915_mock) >logs
$ ./tools/testing/kunit/kunit.py parse logs

> > + /* The kunit module is required for running any kunit tests */
> > + if (igt_kmod_load("kunit", NULL) != 0) {
> > + igt_warn("Unable to load kunit module\n");
> > + goto unload;
> > + }
>
> Do you want to _require_ KUnit be built as a module, rather than built-in here?

I guess it doesn't matter much, for kunit module.

On KUnit test modules themselves, we need to be able to do module
unload/reload, as some IGT tests check or need to do module unload/reload.

> Equally, does this need to mark a failure (or at least "SKIPPED")
> rather than success, in the case it fails.

Agreed.

> > +
> > + if (igt_kmod_load(module_name, opts) != 0) {
> > + igt_warn("Unable to load %s module\n", module_name);
> > + goto unload;
> > + }
>
> As above, should this record a failure, or skip?

Yes, it should be a failure.

> > +
> > + igt_kunit_subtests(tst.kmsg, record, &sublevel, &failed_tests);
> > +unload:
> > + igt_kmod_unload("kunit", 0);
>
> Do you want to unconditionally unload the KUnit module here? It's safe
> (maybe even safer) to leave it loaded between runs of KUnit tests.

Agreed.

Regards,
Mauro

[Mauro Carvalho Chehab]

Hi Isabella,

On Mon, 19 Sep 2022 17:43:19 -0300
Isabella Basso <isab...@riseup.net> wrote:

> > Do you want to _require_ KUnit be built as a module, rather than built-in here?
>

> I’ll change the comment and the warning in v3 to clarify this.

When do you intend to submit v3?

Regards,
Mauro

[Mauro Carvalho Chehab]

On Mon, 19 Sep 2022 17:25:38 -0700
Daniel Latypov <dlat...@google.com> wrote:

> On Mon, Sep 19, 2022 at 1:43 PM Isabella Basso <isab...@riseup.net> wrote:
> > >> + * "(K)TAP version XX" should be the first line on all (sub)tests as per
> > >> + * https://www.kernel.org/doc/html/latest/dev-tools/ktap.html#version-lines
> > >> + * but actually isn't, as it currently depends on whoever writes the
> > >> + * test to print this info
> > >
> > > FYI: we're really trying to fix cases of "missing version lines",
> > > largely by making the kunit_test_suites() macro work in more
> > > circumstances.
> > >
> > > So while it may be worth still handling the case where this is
> > > missing, I don't think there are any tests in the latest versions of
> > > the kernel which should have this missing.
> >
> > I’m not sure if I totally get how these work. Every time I run a KUnit test I
> > get something like this: https://pastebin.com/7Ff31PMC
> >
> > As you can see it has been loaded as a module, just like we intend to do it
> > from IGT, and I see no version lines whatsoever. Am I doing something wrong?
>
> You're doing everything right.
>
> The problem is we only print the version line for the *built-in* tests.
> It never gets printed for tests in loadable modules.

IGT tests require loadable modules, as some tests check if bind/unbind
and load/unload works. Also, some tests require modprobing drivers
with different parameters.

Unfortunately, kunit.py is currently broken on such cases: its parser
simply ignores everything if the subtest doesn't have a TAP version
just before it. See:

$ ./tools/testing/kunit/kunit.py parse /var/log/dmesg
[12:37:05] ============================================================
[12:37:05] [ERROR] Test: main: 0 tests run!
[12:37:05] ============================================================
[12:37:05] Testing complete. Ran 0 tests: errors: 1

Here, I loaded the test module twice. I can force it to parse it by

doing

$ (dmesg|grep "TAP version"; dmesg|grep -A9999 intel_i915_mock) >logs

But then, it gets confused with two subtests with the same name:

$ ./tools/testing/kunit/kunit.py parse logs
[12:37:34] ============================================================
[12:37:34] ============== intel_i915_mock (18 subtests) ===============
[12:37:34] [PASSED] sanitycheck
[12:37:34] [PASSED] shmem
[12:37:34] [PASSED] fence
[12:37:34] [PASSED] scatterlist
[12:37:34] [PASSED] syncmap
[12:37:34] [PASSED] uncore
[12:37:34] [PASSED] ring
[12:37:34] [PASSED] engine
[12:37:34] [PASSED] timelines
[12:37:34] [PASSED] requests
[12:37:34] [PASSED] objects
[12:37:34] [PASSED] phys
[12:37:34] [PASSED] dmabuf
[12:37:34] [PASSED] vma
[12:37:34] [PASSED] evict
[12:37:34] [PASSED] gtt
[12:37:34] [PASSED] hugepages
[12:37:34] [PASSED] memory_region
[12:37:34] ================= [PASSED] intel_i915_mock =================
[12:37:34] ============== intel_i915_mock (18 subtests) ===============
[12:37:34] [PASSED] sanitycheck
[12:37:34] [PASSED] shmem
[12:37:34] [PASSED] fence
[12:37:34] [PASSED] scatterlist
[12:37:34] [PASSED] syncmap
[12:37:34] [PASSED] uncore
[12:37:34] [PASSED] ring
[12:37:34] [PASSED] engine
[12:37:34] [PASSED] timelines
[12:37:34] [PASSED] requests
[12:37:34] [PASSED] objects
[12:37:34] [PASSED] phys
[12:37:34] [PASSED] dmabuf
[12:37:34] [PASSED] vma
[12:37:34] [PASSED] evict
[12:37:34] [PASSED] gtt
[12:37:34] [PASSED] hugepages
[12:37:34] [PASSED] memory_region
[12:37:34] [ERROR] Test: intel_i915_mock: Expected test number 2 but found 1
[12:37:34] ================= [PASSED] intel_i915_mock =================
[12:37:34] ============================================================
[12:37:34] Testing complete. Ran 36 tests: passed: 36, errors: 1

> Some more details below, if interested.
> Specifically, it happens in
> https://elixir.bootlin.com/linux/latest/C/ident/kunit_print_tap_header
>
> What David is referring to is we had tests that weren't in modules,
> but didn't use the normal built-in code path. Those were also missing
> TAP version lines.
> But KUnit needs to do better here in the case of modules.
>
> The goal was that you'd be able to parse the result of module based
> tests by something like
> $ cat /sys/kernel/debug/kunit/*/results | ./tools/testing/kunit/kunit.py parse
> but this doesn't work because of the lack of a version line.

At least here, debug/kunit doesn't exist:

sudo ls -lctra /sys/kernel/debug/|grep kunit

>
> If we add it to each module's test results, then we'll need to update
> the parse to allow multiple verison lines, I think.

Yeah, the parser is currently broken when used with modules.

Regards,
Mauro

[Mauro Carvalho Chehab]

I don't think so. I created a KUnit with the mock selftests:

$ modinfo test-i915-mock
filename: /lib/modules/6.1.0-rc2-drm-b1cab854a639+/kernel/drivers/gpu/drm/i915/test-i915-mock.ko
import_ns: I915_SELFTEST
license: GPL v2
depends: i915
retpoline: Y
intree: Y
name: test_i915_mock
vermagic: 6.1.0-rc2-drm-b1cab854a639+ SMP preempt mod_unload

There's no module parameters. Just loading it makes all tests
there to run.

OK, with the current implementation, we could have one module per subtest,
but that sounds overkill.

Another possibility would be to implement it like:

test-i915-mock-fences
test-i915-mock-hugepages
...

which would allow a finer control. Another possibility would be to
change kunit_suite and kunit_test_suites() to optionally create
a modprobe parameter to allow specifying what tests from the test
suites would run.

On the other hand, not sure if are there any gains implementing it,
at least for the hardware-independent tests. I mean, if one of such
tests fail after a patch, the change is broken and should be reverted,
as this is a regression.

> Orthogonal to that question, drm_mm and test-drm_modeset are _now_
> using kunit but in LTS kernels they're not, and we'd like to be able
> to keep testing those. That means having both launchers here and just
> letting the "incorrect" one produce a 'skip'.

Agreed. Patch 4/4 should be checking if the test module is there.
If not, fall back to selftest.

Regards,
Mauro

[Petri Latvala]

Ah, the selection is in kunit.ko itself. kunit.filter_glob, set from
kunit.py with

positional arguments:
filter_glob Filter which KUnit test suites/tests run at boot-time, e.g. list* or list*.*del_test



--
Petri Latvala

[Mauro Carvalho Chehab]

On Tue, 1 Nov 2022 15:16:02 +0200

> \

Gah, permissions are 0:

module_param_named(filter_glob, filter_glob_param, charp, 0);

You can't even see what filters were set via sysfs:

$ ls /sys/module/kunit/parameters/
stats_enabled

So, once set, there's no way to change it.

I wonder why this isn't 0x644.

It sounds that, if we want to control it at runtime, we'll need to
build with kunit as module, and unload/reload it every time if/when
we want to run IGT with a different filtering ruleset.

Regards,
Mauro

[Daniel Latypov]

On Tue, Nov 1, 2022, 6:53 AM Mauro Carvalho Chehab
<mauro....@linux.intel.com> wrote:
> > Ah, the selection is in kunit.ko itself. kunit.filter_glob, set from
> > kunit.py with
> >
> > positional arguments:
> > filter_glob Filter which KUnit test suites/tests run at boot-time, e.g. list* or list*.*del_test
> > \
>
> Gah, permissions are 0:
>
> module_param_named(filter_glob, filter_glob_param, charp, 0);
>
> You can't even see what filters were set via sysfs:
>
> $ ls /sys/module/kunit/parameters/
> stats_enabled
>
> So, once set, there's no way to change it.
>
> I wonder why this isn't 0x644.
>
> It sounds that, if we want to control it at runtime, we'll need to
> build with kunit as module, and unload/reload it every time if/when
> we want to run IGT with a different filtering ruleset.

kunit.filter_glob only works on built-in tests, which is why you can
only set it once atm.
There is no currently no way for KUnit to run a subset of tests in modules.

The module init code is here:
https://elixir.bootlin.com/linux/v6.0/source/lib/kunit/test.c#L620
As you can see, that func it calls just initializes and runs all the
suites: https://elixir.bootlin.com/linux/v6.0/source/lib/kunit/test.c#L589

This can of course be changed, just needs some work on the KUnit-side.

Daniel

[Isabella Basso]

Hi, Mauro,

I’m currently waiting for my peers to review some refactorings and test
things thoroughly. I hope to submit it in a week or two. Sorry it’s taking so
long.

Cheers,
--
Isabella Basso

> Regards,
> Mauro

[Mauro Carvalho Chehab]

On Tue, 1 Nov 2022 14:17:26 -0300

Isabella Basso <isab...@riseup.net> wrote:

> Hi, Mauro,
>
> > Am 01/11/2022 um 9:33 AM schrieb Mauro Carvalho Chehab <mauro....@linux.intel.com>:
> >
> > Hi Isabella,
> >
> > On Mon, 19 Sep 2022 17:43:19 -0300
> > Isabella Basso <isab...@riseup.net> wrote:
> >
> >>> Do you want to _require_ KUnit be built as a module, rather than built-in here?
> >>
> >> I’ll change the comment and the warning in v3 to clarify this.
> >
> > When do you intend to submit v3?
>
> I’m currently waiting for my peers to review some refactorings and test
> things thoroughly. I hope to submit it in a week or two. Sorry it’s taking so
> long.

No problem. In the mean time, I'll try to do some tests with the current
version.

Btw, if you want, you can also check the RFC patch I submitted today, adding
KUnit support for i915:

https://patchwork.freedesktop.org/patch/509448/?series=110384&rev=1

The tests there are hardware-independent, but they need to be built
using x86_64 arch, due to i915 dependencies.

Regards,
Mauro

[Mauro Carvalho Chehab]

On Sun, 28 Aug 2022 21:09:19 -0300
Isabella Basso <isab...@riseup.net> wrote:

> This adds functions for both executing the tests as well as parsing (K)TAP
> kmsg output, as per the KTAP spec [1].
>
> [1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html
>
> Signed-off-by: Isabella Basso <isab...@riseup.net>

Hi Isabella,

I'm doing some tests here with my i915 KUnit patch series.

There's a problem with the way it is currently parsing the KTAP logs on
IGT. It sounds that it is parsing the data only at the end, and not as
they arrive. That's bad, as if something goes wrong, the previously
reported data is still useful.

Also, when there's a crash, the IGT process is getting segmentation
fault. So, the end result is that nothing is actually reported.

$ sudo ./build/tests/i915_selftest
IGT-Version: 1.26-gbab20eb65 (x86_64) (Linux: 6.1.0-rc2-drm-990037e9984e+ x86_64)
Segmentation fault (core dumped)

However, the logs are there (see enclosed). In this specific case, there
was a GPU hang while running one of the tests on a real hardware, which
is something that it is actually expected at development time.

FYI, those are the logs (when using the patches I'm still developing
to run selftests via KUnit - currently broken):

[ 360.446771] [IGT] i915_selftest: executing
[ 360.465611] # Subtest: i915 mock selftests
[ 360.465614] 1..18
[ 360.466163] i915: i915_mock_sanitycheck() - ok!
[ 360.466273] ok 1 - mock_sanitycheck
[ 360.466428] i915: Running shmem_utils_mock_selftests/igt_shmem_basic
[ 360.466500] ok 2 - mock_shmem
[ 360.466592] i915: Running i915_sw_fence_mock_selftests/test_self
[ 360.466633] i915: Running i915_sw_fence_mock_selftests/test_dag
[ 360.466645] i915: Running i915_sw_fence_mock_selftests/test_AB
[ 360.466692] i915: Running i915_sw_fence_mock_selftests/test_ABC
[ 360.466729] i915: Running i915_sw_fence_mock_selftests/test_AB_C
[ 360.466764] i915: Running i915_sw_fence_mock_selftests/test_C_AB
[ 360.466800] i915: Running i915_sw_fence_mock_selftests/test_chain
[ 360.502903] i915: Running i915_sw_fence_mock_selftests/test_ipc
[ 360.505338] i915: Running i915_sw_fence_mock_selftests/test_timer
[ 366.490222] i915: Running i915_sw_fence_mock_selftests/test_dma_fence
[ 367.146210] Asynchronous wait on fence mock:mock:0 timed out (hint:fence_notify [i915])
[ 367.147793] ok 3 - mock_fence
[ 367.148388] i915: Running scatterlist_mock_selftests/igt_sg_alloc
[ 367.648994] sg_alloc_table timed out
[ 367.649003] i915: Running scatterlist_mock_selftests/igt_sg_trim
[ 368.149994] i915_sg_trim timed out
[ 368.150095] ok 4 - mock_scatterlist
[ 368.150423] i915: Running i915_syncmap_mock_selftests/igt_syncmap_init
[ 368.150446] i915: Running i915_syncmap_mock_selftests/igt_syncmap_one
[ 368.651091] i915: Running i915_syncmap_mock_selftests/igt_syncmap_join_above
[ 368.651240] i915: Running i915_syncmap_mock_selftests/igt_syncmap_join_below
[ 368.652311] i915: Running i915_syncmap_mock_selftests/igt_syncmap_neighbours
[ 369.965095] i915: Running i915_syncmap_mock_selftests/igt_syncmap_compact
[ 369.965989] i915: Running i915_syncmap_mock_selftests/igt_syncmap_random
[ 370.482663] ok 5 - mock_syncmap
[ 370.482853] ok 6 - mock_uncore
[ 370.483119] i915: Running intel_ring_mock_selftests/igt_ring_direction
[ 370.483171] ok 7 - mock_ring
[ 370.483328] i915: Running intel_engine_cs_mock_selftests/intel_mmio_bases_check
[ 370.483399] ok 8 - mock_engine
[ 370.483456] i915: Running intel_timeline_mock_selftests/mock_hwsp_freelist
[ 370.484028] mock: [drm] Using Transparent Hugepages
[ 370.484164] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 370.484195] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 370.484224] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 372.258731] i915: Running intel_timeline_mock_selftests/igt_sync
[ 372.262110] i915: Running intel_timeline_mock_selftests/bench_sync
[ 372.463995] bench_sync: 43371 random insertions, 2323ns/insert
[ 372.467075] bench_sync: 43371 random lookups, 65ns/lookup
[ 372.702995] bench_sync: 836833 in-order insertions, 119ns/insert
[ 372.705534] bench_sync: 836833 in-order lookups, 3ns/lookup
[ 372.914994] bench_sync: 6214645 repeated insert/lookups, 11ns/op
[ 373.015994] bench_sync: 19605180 cyclic/1 insert/lookups, 5ns/op
[ 373.116994] bench_sync: 18945372 cyclic/2 insert/lookups, 5ns/op
[ 373.217994] bench_sync: 16210409 cyclic/3 insert/lookups, 6ns/op
[ 373.318995] bench_sync: 14141870 cyclic/5 insert/lookups, 7ns/op
[ 373.419994] bench_sync: 12728929 cyclic/8 insert/lookups, 7ns/op
[ 373.520995] bench_sync: 9070286 cyclic/13 insert/lookups, 11ns/op
[ 373.639995] bench_sync: 52516 cyclic/21 insert/lookups, 1921ns/op
[ 373.762920] ok 9 - mock_timelines
[ 373.763522] mock: [drm] Using Transparent Hugepages
[ 373.763575] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 373.763590] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 373.763604] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 373.763793] i915: Running i915_request_mock_selftests/igt_add_request
[ 373.764100] i915: Running i915_request_mock_selftests/igt_wait_request
[ 374.274884] i915: Running i915_request_mock_selftests/igt_fence_wait
[ 374.786370] i915: Running i915_request_mock_selftests/igt_request_rewind
[ 374.789600] i915: Running i915_request_mock_selftests/mock_breadcrumbs_smoketest
[ 375.516775] Completed 82 waits for 52186 fence across 8 cpus
[ 375.703841] ok 10 - mock_requests
[ 375.705131] mock: [drm] Using Transparent Hugepages
[ 375.705270] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 375.705320] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 375.705367] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 375.705875] i915: Running i915_gem_object_mock_selftests/igt_gem_object
[ 375.747736] ok 11 - mock_objects
[ 375.749088] mock: [drm] Using Transparent Hugepages
[ 375.749239] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 375.749292] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 375.749343] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 375.749843] i915: Running i915_gem_phys_mock_selftests/mock_phys_object
[ 375.794834] ok 12 - mock_phys
[ 375.796067] mock: [drm] Using Transparent Hugepages
[ 375.796208] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 375.796258] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 375.796304] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 375.796775] i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_export
[ 375.797036] i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import_self
[ 375.797192] i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import
[ 375.797541] i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import_ownership
[ 375.801328] i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_export_vmap
[ 375.803245] ok 13 - mock_dmabuf
[ 375.804878] mock: [drm] Using Transparent Hugepages
[ 375.805124] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 375.805236] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 375.805343] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 375.806192] i915: Running i915_vma_mock_selftests/igt_vma_create
[ 376.308125] igt_vma_create timed out: after 31 objects in 83 contexts
[ 376.311056] i915: Running i915_vma_mock_selftests/igt_vma_pin1
[ 376.311803] i915: Running i915_vma_mock_selftests/igt_vma_rotate_remap
[ 379.883757] i915: Running i915_vma_mock_selftests/igt_vma_partial
[ 383.085953] ok 14 - mock_vma
[ 383.087159] mock: [drm] Using Transparent Hugepages
[ 383.087295] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 383.087345] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 383.087391] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 383.087885] i915: Running i915_gem_evict_mock_selftests/igt_evict_something
[ 383.259301] i915: Running i915_gem_evict_mock_selftests/igt_evict_for_vma
[ 383.429083] i915: Running i915_gem_evict_mock_selftests/igt_evict_for_cache_color
[ 383.439038] i915: Running i915_gem_evict_mock_selftests/igt_evict_vm
[ 383.617849] i915: Running i915_gem_evict_mock_selftests/igt_overcommit
[ 383.814683] ok 15 - mock_evict
[ 383.815450] mock: [drm] Using Transparent Hugepages
[ 383.815535] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 383.815565] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 383.815593] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 383.815893] i915: Running i915_gem_gtt_mock_selftests/igt_mock_drunk
[ 384.316018] drunk_hole timed out after 30852/524288
[ 384.316205] i915: Running i915_gem_gtt_mock_selftests/igt_mock_walk
[ 384.817415] walk_hole timed out at 7d19000
[ 384.817433] i915: Running i915_gem_gtt_mock_selftests/igt_mock_pot
[ 385.793876] pot_hole timed out after 19/33
[ 385.793895] i915: Running i915_gem_gtt_mock_selftests/igt_mock_fill
[ 386.294465] fill_hole timed out (npages=1, prime=191)
[ 386.294518] i915: Running i915_gem_gtt_mock_selftests/igt_gtt_reserve
[ 386.451741] i915: Running i915_gem_gtt_mock_selftests/igt_gtt_insert
[ 386.778843] ok 16 - mock_gtt
[ 386.780179] mock: [drm] Using Transparent Hugepages
[ 386.780313] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 386.780362] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 386.780409] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 386.781221] i915: Running i915_gem_huge_page_mock_selftests/igt_mock_exhaust_device_supported_pages
[ 386.792539] i915: Running i915_gem_huge_page_mock_selftests/igt_mock_memory_region_huge_pages
[ 386.796808] i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_misaligned_dma
[ 386.895508] i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_huge_fill
[ 387.396087] igt_mock_ppgtt_huge_fill timed out at size 51187712
[ 387.397014] i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_64K
[ 387.912504] ok 17 - mock_hugepages
[ 387.913155] mock: [drm] Using Transparent Hugepages
[ 387.913236] mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
[ 387.913263] mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
[ 387.913288] mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
[ 387.913584] i915: Running intel_memory_region_mock_selftests/igt_mock_reserve
[ 387.949404] i915: Running intel_memory_region_mock_selftests/igt_mock_fill
[ 388.002432] i915: Running intel_memory_region_mock_selftests/igt_mock_contiguous
[ 389.352514] i915: Running intel_memory_region_mock_selftests/igt_mock_splintered_region
[ 389.383240] i915: Running intel_memory_region_mock_selftests/igt_mock_max_segment
[ 389.413338] i915: Running intel_memory_region_mock_selftests/igt_mock_io_size
[ 389.413361] igt_mock_io_size with ps=10000, io_size=ae010000, total=fb760000
[ 389.417103] igt_mock_io_size mappable theft=(0MiB/2784MiB), total=4023MiB
[ 389.477896] ok 18 - mock_memory_region
[ 389.477907] # i915 mock selftests: pass:18 fail:0 skip:0 total:18
[ 389.477943] # Totals: pass:18 fail:0 skip:0 total:18
[ 389.477983] ok 1 - i915 mock selftests
[ 389.478139] 0000:00:02.0: it is a i915 device.
[ 389.478222] # Subtest: i915 perf selftests
[ 389.478226] 1..4
[ 389.478550] i915: Running intel_engine_cs_perf_selftests/perf_mi_bb_start
[ 389.482084] rcs0: MI_BB_START cycles: 1073741589
[ 389.487351] bcs0: MI_BB_START cycles: 1073741587
[ 389.488363] vcs0: MI_BB_START cycles: 1073741586
[ 389.489321] vcs1: MI_BB_START cycles: 1073741586
[ 389.490187] vecs0: MI_BB_START cycles: 30
[ 389.503281] i915: Running intel_engine_cs_perf_selftests/perf_mi_noop
[ 389.505789] rcs0: 16K MI_NOOP cycles: 856
[ 389.506974] bcs0: 16K MI_NOOP cycles: 780
[ 389.508335] vcs0: 16K MI_NOOP cycles: 783
[ 389.509412] vcs1: 16K MI_NOOP cycles: 781
[ 389.510599] vecs0: 16K MI_NOOP cycles: 782
[ 389.527204] ok 1 - perf_engine_cs
[ 389.527350] i915: Running i915_request_perf_selftests/perf_request_latency
[ 389.528341] rcs0: semaphore response 22 cycles, 1185ns
[ 389.529044] rcs0: idle dispatch latency 719 cycles, 37474ns
[ 389.529730] rcs0: busy dispatch latency 298 cycles, 15547ns
[ 389.530396] rcs0: inter-request latency 276 cycles, 14401ns
[ 389.531663] rcs0: context switch latency 806 cycles, 41992ns
[ 389.532680] rcs0: preemption dispatch latency 1212 cycles, 63164ns
[ 389.532707] rcs0: preemption switch latency 710 cycles, 36992ns
[ 389.533422] rcs0: completion latency 871 cycles, 45365ns
[ 389.534044] bcs0: semaphore response 16 cycles, 873ns
[ 389.534834] bcs0: idle dispatch latency 433 cycles, 22578ns
[ 389.535311] bcs0: busy dispatch latency 314 cycles, 16380ns
[ 389.535678] bcs0: inter-request latency 44 cycles, 2292ns
[ 389.536285] bcs0: context switch latency 199 cycles, 10391ns
[ 389.536901] bcs0: preemption dispatch latency 730 cycles, 38060ns
[ 389.536918] bcs0: preemption switch latency 761 cycles, 39662ns
[ 389.537534] bcs0: completion latency 948 cycles, 49401ns
[ 389.538087] vcs0: semaphore response 18 cycles, 977ns
[ 389.538868] vcs0: idle dispatch latency 472 cycles, 24584ns
[ 389.539400] vcs0: busy dispatch latency 331 cycles, 17279ns
[ 389.539783] vcs0: inter-request latency 50 cycles, 2643ns
[ 389.540422] vcs0: context switch latency 183 cycles, 9531ns
[ 389.541071] vcs0: preemption dispatch latency 691 cycles, 36003ns
[ 389.541089] vcs0: preemption switch latency 688 cycles, 35860ns
[ 389.541615] vcs0: completion latency 655 cycles, 34128ns
[ 389.542162] vcs1: semaphore response 17 cycles, 899ns
[ 389.542811] vcs1: idle dispatch latency 424 cycles, 22097ns
[ 389.543125] vcs1: busy dispatch latency 207 cycles, 10808ns
[ 389.543449] vcs1: inter-request latency 52 cycles, 2709ns
[ 389.543988] vcs1: context switch latency 190 cycles, 9909ns
[ 389.544652] vcs1: preemption dispatch latency 701 cycles, 36511ns
[ 389.544669] vcs1: preemption switch latency 492 cycles, 25625ns
[ 389.545148] vcs1: completion latency 461 cycles, 24037ns
[ 389.545692] vecs0: semaphore response 19 cycles, 990ns
[ 389.546244] vecs0: idle dispatch latency 443 cycles, 23112ns
[ 389.546691] vecs0: busy dispatch latency 261 cycles, 13633ns
[ 389.547013] vecs0: inter-request latency 49 cycles, 2591ns
[ 389.547594] vecs0: context switch latency 184 cycles, 9610ns
[ 389.548187] vecs0: preemption dispatch latency 779 cycles, 40612ns
[ 389.548205] vecs0: preemption switch latency 451 cycles, 23503ns
[ 389.548688] vecs0: completion latency 484 cycles, 25248ns
[ 389.549042] i915: Running i915_request_perf_selftests/perf_series_engines
[ 390.051955] s_sync0 [i915] rcs0: { seqno:1244, busy:42.80%, runtime:94ms, walltime:500ms }
[ 390.052112] s_sync0 [i915] bcs0: { seqno:1242, busy:9.30%, runtime:5ms, walltime:501ms }
[ 390.052281] s_sync0 [i915] vcs0: { seqno:1242, busy:15.19%, runtime:0ms, walltime:501ms }
[ 390.052449] s_sync0 [i915] vcs1: { seqno:1242, busy:12.92%, runtime:0ms, walltime:501ms }
[ 390.052578] s_sync0 [i915] vecs0: { seqno:1242, busy:13.50%, runtime:0ms, walltime:502ms }
[ 390.553986] s_sync1 [i915] rcs0: { seqno:3072, busy:65.88%, runtime:142ms, walltime:500ms }
[ 390.554133] s_sync1 [i915] bcs0: { seqno:3068, busy:13.78%, runtime:0ms, walltime:501ms }
[ 390.554301] s_sync1 [i915] vcs0: { seqno:3068, busy:20.48%, runtime:18ms, walltime:501ms }
[ 390.554489] s_sync1 [i915] vcs1: { seqno:3068, busy:28.32%, runtime:21ms, walltime:501ms }
[ 390.554622] s_sync1 [i915] vecs0: { seqno:3068, busy:16.87%, runtime:19ms, walltime:501ms }
[ 391.055401] s_many [i915] rcs0: { seqno:11728, busy:75.43%, runtime:148ms, walltime:500ms }
[ 391.055525] s_many [i915] bcs0: { seqno:11724, busy:67.28%, runtime:24ms, walltime:500ms }
[ 391.055654] s_many [i915] vcs0: { seqno:11724, busy:72.88%, runtime:21ms, walltime:500ms }
[ 391.055782] s_many [i915] vcs1: { seqno:11724, busy:74.87%, runtime:18ms, walltime:500ms }
[ 391.055880] s_many [i915] vecs0: { seqno:11724, busy:73.76%, runtime:17ms, walltime:500ms }
[ 391.055938] i915: Running i915_request_perf_selftests/perf_parallel_engines
[ 391.559973] p_sync0 [i915] rcs0: { count:4423, busy:92.58%, runtime:129ms, walltime:500ms }
[ 391.560023] p_sync0 [i915] bcs0: { count:5712, busy:88.20%, runtime:18ms, walltime:500ms }
[ 391.560050] p_sync0 [i915] vcs0: { count:5825, busy:90.94%, runtime:25ms, walltime:500ms }
[ 391.560076] p_sync0 [i915] vcs1: { count:5875, busy:91.26%, runtime:24ms, walltime:500ms }
[ 391.560103] p_sync0 [i915] vecs0: { count:5929, busy:90.34%, runtime:23ms, walltime:500ms }
[ 392.063758] p_sync1 [i915] rcs0: { count:5727, busy:95.73%, runtime:171ms, walltime:500ms }
[ 392.063794] p_sync1 [i915] bcs0: { count:10548, busy:86.66%, runtime:30ms, walltime:500ms }
[ 392.063823] p_sync1 [i915] vcs0: { count:9614, busy:88.67%, runtime:35ms, walltime:500ms }
[ 392.063851] p_sync1 [i915] vcs1: { count:8445, busy:90.05%, runtime:30ms, walltime:500ms }
[ 392.063879] p_sync1 [i915] vecs0: { count:9894, busy:88.79%, runtime:33ms, walltime:500ms }
[ 392.567890] p_many [i915] rcs0: { count:16814, busy:99.99%, runtime:303ms, walltime:500ms }
[ 392.567923] p_many [i915] bcs0: { count:20754, busy:99.98%, runtime:49ms, walltime:500ms }
[ 392.567949] p_many [i915] vcs0: { count:15965, busy:99.39%, runtime:48ms, walltime:500ms }
[ 392.567976] p_many [i915] vcs1: { count:20270, busy:99.36%, runtime:61ms, walltime:500ms }
[ 392.568017] p_many [i915] vecs0: { count:16736, busy:99.99%, runtime:48ms, walltime:500ms }
[ 392.568082] ok 2 - perf_request
[ 392.568155] i915: Running intel_migrate_perf_selftests/perf_clear_blt
[ 392.569089] bcs0: 4 KiB fill: 40 MiB/s
[ 392.570259] bcs0: 64 KiB fill: 419 MiB/s
[ 392.573495] bcs0: 2048 KiB fill: 3143 MiB/s
[ 392.656686] bcs0: 65536 KiB fill: 3856 MiB/s
[ 392.674288] i915: Running intel_migrate_perf_selftests/perf_copy_blt
[ 392.677148] bcs0: 4 KiB copy: 18 MiB/s
[ 392.678227] bcs0: 64 KiB copy: 394 MiB/s
[ 392.680686] bcs0: 2048 KiB copy: 4774 MiB/s
[ 392.709356] bcs0: 65536 KiB copy: 11604 MiB/s
[ 392.738410] ok 3 - perf_migrate
[ 392.738853] i915: Running intel_memory_region_perf_selftests/perf_memcpy
[ 392.739161] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy 4 KiB copy: 8159 MiB/s
[ 392.739223] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy_long 4 KiB copy: 3547 MiB/s
[ 392.739279] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy_from_wc 4 KiB copy: 5086 MiB/s
[ 392.749402] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy 4 KiB copy: 5101 MiB/s
[ 392.749482] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy_long 4 KiB copy: 1317 MiB/s
[ 392.749540] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy_from_wc 4 KiB copy: 5056 MiB/s
[ 392.757570] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy 4 KiB copy: 375 MiB/s
[ 392.758079] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy_long 4 KiB copy: 49 MiB/s
[ 392.758146] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy_from_wc 4 KiB copy: 2390 MiB/s
[ 392.769568] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy 4 KiB copy: 207 MiB/s
[ 392.770434] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy_long 4 KiB copy: 26 MiB/s
[ 392.770507] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy_from_wc 4 KiB copy: 2203 MiB/s
[ 392.779083] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy 64 KiB copy: 14154 MiB/s
[ 392.779308] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy_long 64 KiB copy: 2052 MiB/s
[ 392.779442] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy_from_wc 64 KiB copy: 4238 MiB/s
[ 392.787666] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy 64 KiB copy: 8516 MiB/s
[ 392.788092] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy_long 64 KiB copy: 1064 MiB/s
[ 392.788196] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy_from_wc 64 KiB copy: 7800 MiB/s
[ 392.797953] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy 64 KiB copy: 233 MiB/s
[ 392.805504] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy_long 64 KiB copy: 44 MiB/s
[ 392.805649] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy_from_wc 64 KiB copy: 3604 MiB/s
[ 392.813866] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy 64 KiB copy: 236 MiB/s
[ 392.825378] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy_long 64 KiB copy: 29 MiB/s
[ 392.825484] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy_from_wc 64 KiB copy: 4544 MiB/s
[ 392.835450] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy 4096 KiB copy: 14838 MiB/s
[ 392.839633] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy_long 4096 KiB copy: 4779 MiB/s
[ 392.841384] _perf_memcpy src(system, WB) -> dst(system, WB) memcpy_from_wc 4096 KiB copy: 11442 MiB/s
[ 392.853446] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy 4096 KiB copy: 23125 MiB/s
[ 392.858952] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy_long 4096 KiB copy: 3847 MiB/s
[ 392.859638] _perf_memcpy src(system, WB) -> dst(system, WC) memcpy_from_wc 4096 KiB copy: 31140 MiB/s
[ 392.904274] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy 4096 KiB copy: 488 MiB/s
[ 393.154071] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy_long 4096 KiB copy: 80 MiB/s
[ 393.157632] _perf_memcpy src(system, WC) -> dst(system, WB) memcpy_from_wc 4096 KiB copy: 5844 MiB/s
[ 393.217217] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy 4096 KiB copy: 390 MiB/s
[ 393.632277] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy_long 4096 KiB copy: 48 MiB/s
[ 393.636491] _perf_memcpy src(system, WC) -> dst(system, WC) memcpy_from_wc 4096 KiB copy: 4770 MiB/s
[ 393.815263] ok 4 - perf_region
[ 393.815273] # i915 perf selftests: pass:4 fail:0 skip:0 total:4
[ 393.815302] # Totals: pass:4 fail:0 skip:0 total:4
[ 393.815336] ok 2 - i915 perf selftests
[ 393.815391] 0000:00:02.0: it is a i915 device.
[ 393.815462] # Subtest: i915 live selftests
[ 393.815465] 1..36
[ 393.815954] i915: i915_live_sanitycheck() - ok!
[ 393.816064] ok 1 - live_sanitycheck
[ 393.816362] i915: Running intel_uncore_live_selftests/live_fw_table
[ 393.816437] i915: Running intel_uncore_live_selftests/live_forcewake_ops
[ 393.816481] i915: Running intel_uncore_live_selftests/live_forcewake_domains
[ 393.816539] ok 2 - live_uncore
[ 393.816858] i915: Running intel_workarounds_live_selftests/live_dirty_whitelist
[ 393.841295] i915: Running intel_workarounds_live_selftests/live_reset_whitelist
[ 393.841352] Checking 3 whitelisted registers on rcs0 (RING_NONPRIV) [engine]
[ 393.845858] i915 0000:00:02.0: [drm] Resetting rcs0 for live_workarounds
[ 393.847548] Checking 3 whitelisted registers on rcs0 (RING_NONPRIV) [device]
[ 393.850443] i915 0000:00:02.0: [drm] Resetting chip for live_workarounds
[ 393.853525] Checking 1 whitelisted registers on bcs0 (RING_NONPRIV) [engine]
[ 393.855767] i915 0000:00:02.0: [drm] Resetting bcs0 for live_workarounds
[ 393.856868] Checking 1 whitelisted registers on bcs0 (RING_NONPRIV) [device]
[ 393.858487] i915 0000:00:02.0: [drm] Resetting chip for live_workarounds
[ 393.859723] Checking 1 whitelisted registers on vcs0 (RING_NONPRIV) [engine]
[ 393.861129] i915 0000:00:02.0: [drm] Resetting vcs0 for live_workarounds
[ 393.861651] Checking 1 whitelisted registers on vcs0 (RING_NONPRIV) [device]
[ 393.862615] i915 0000:00:02.0: [drm] Resetting chip for live_workarounds
[ 393.863976] Checking 1 whitelisted registers on vcs1 (RING_NONPRIV) [engine]
[ 393.864833] i915 0000:00:02.0: [drm] Resetting vcs1 for live_workarounds
[ 393.865291] Checking 1 whitelisted registers on vcs1 (RING_NONPRIV) [device]
[ 393.866205] i915 0000:00:02.0: [drm] Resetting chip for live_workarounds
[ 393.867434] Checking 1 whitelisted registers on vecs0 (RING_NONPRIV) [engine]
[ 393.868320] i915 0000:00:02.0: [drm] Resetting vecs0 for live_workarounds
[ 393.868854] Checking 1 whitelisted registers on vecs0 (RING_NONPRIV) [device]
[ 393.869720] i915 0000:00:02.0: [drm] Resetting chip for live_workarounds
[ 393.889458] i915: Running intel_workarounds_live_selftests/live_isolated_whitelist
[ 393.912185] i915: Running intel_workarounds_live_selftests/live_gpu_reset_workarounds
[ 393.912262] Verifying after GPU reset...
[ 393.917792] i915 0000:00:02.0: [drm] Resetting chip for live_workarounds
[ 393.944251] i915: Running intel_workarounds_live_selftests/live_engine_reset_workarounds
[ 393.944505] Verifying after rcs0 reset...
[ 393.950041] i915 0000:00:02.0: [drm] Resetting rcs0 for live_workarounds:idle
[ 393.957254] i915 0000:00:02.0: [drm] Resetting rcs0 for live_workarounds:active
[ 393.961244] Verifying after bcs0 reset...
[ 393.967352] i915 0000:00:02.0: [drm] Resetting bcs0 for live_workarounds:active
[ 393.969645] Verifying after vcs0 reset...
[ 393.971661] i915 0000:00:02.0: [drm] Resetting vcs0 for live_workarounds:idle
[ 393.974734] i915 0000:00:02.0: [drm] Resetting vcs0 for live_workarounds:active
[ 393.976954] Verifying after vcs1 reset...
[ 393.979056] i915 0000:00:02.0: [drm] Resetting vcs1 for live_workarounds:idle
[ 393.981775] i915 0000:00:02.0: [drm] Resetting vcs1 for live_workarounds:active
[ 393.983983] Verifying after vecs0 reset...
[ 393.986115] i915 0000:00:02.0: [drm] Resetting vecs0 for live_workarounds:idle
[ 393.989148] i915 0000:00:02.0: [drm] Resetting vecs0 for live_workarounds:active
[ 394.025622] ok 3 - live_workarounds
[ 394.025961] i915: Running live_engine_pm_selftests/live_engine_timestamps
[ 394.030557] rcs0 elapsed:100263ns, CTX_TIMESTAMP:105730ns, RING_TIMESTAMP:105730ns
[ 394.032965] bcs0 elapsed:100761ns, CTX_TIMESTAMP:104428ns, RING_TIMESTAMP:104428ns
[ 394.034534] vcs0 elapsed:100558ns, CTX_TIMESTAMP:104688ns, RING_TIMESTAMP:104688ns
[ 394.036012] vcs1 elapsed:100622ns, CTX_TIMESTAMP:104740ns, RING_TIMESTAMP:104740ns
[ 394.037484] vecs0 elapsed:100303ns, CTX_TIMESTAMP:104688ns, RING_TIMESTAMP:104688ns
[ 394.052331] i915: Running live_engine_pm_selftests/live_engine_busy_stats
[ 394.113232] i915: Running live_engine_pm_selftests/live_engine_pm
[ 394.116052] ok 4 - live_gt_engines
[ 394.116477] i915: Running intel_timeline_live_selftests/live_hwsp_recycle
[ 396.644419] i915: Running intel_timeline_live_selftests/live_hwsp_engine
[ 398.097352] i915: Running intel_timeline_live_selftests/live_hwsp_alternate
[ 400.477486] i915: Running intel_timeline_live_selftests/live_hwsp_wrap

[ 400.477647] ======================================================
[ 400.477650] WARNING: possible circular locking dependency detected
[ 400.477652] 6.1.0-rc2-drm-990037e9984e+ #11 Tainted: G N
[ 400.477655] ------------------------------------------------------
[ 400.477657] kunit_try_catch/2002 is trying to acquire lock:
[ 400.477659] ffff888118627078 (&timeline->mutex/1){+.+.}-{3:3}, at: live_hwsp_wrap+0x291/0x690 [i915]
[ 400.477833]
but task is already holding lock:
[ 400.477835] ffff888116cd9078 (kernel_context){+.+.}-{3:3}, at: i915_request_create+0x168/0x230 [i915]
[ 400.477983]
which lock already depends on the new lock.

[ 400.477986]
the existing dependency chain (in reverse order) is:
[ 400.477988]
-> #2 (kernel_context){+.+.}-{3:3}:
[ 400.477992] __mutex_lock+0xca/0x8c0
[ 400.477997] i915_request_create+0x168/0x230 [i915]
[ 400.478155] engine_wa_list_verify+0x368/0xa20 [i915]
[ 400.478304] intel_engine_verify_workarounds+0x23/0x30 [i915]
[ 400.478443] intel_gt_init+0x592/0x700 [i915]
[ 400.478576] i915_gem_init+0x1e9/0x330 [i915]
[ 400.478727] i915_driver_probe+0xee9/0x1770 [i915]
[ 400.478856] i915_pci_probe+0x89/0x3b0 [i915]
[ 400.478985] pci_device_probe+0x97/0x110
[ 400.478989] really_probe+0xdb/0x380
[ 400.478993] __driver_probe_device+0x78/0x170
[ 400.478996] driver_probe_device+0x1f/0x90
[ 400.478998] __driver_attach+0xd5/0x1d0
[ 400.479001] bus_for_each_dev+0x87/0xd0
[ 400.479003] bus_add_driver+0x1b1/0x200
[ 400.479006] driver_register+0x89/0xe0
[ 400.479009] i915_pci_register_driver+0x27/0x40 [i915]
[ 400.479138] mei_cancel_work+0x26/0x30 [mei]
[ 400.479145] do_one_initcall+0x6b/0x310
[ 400.479149] do_init_module+0x76/0x210
[ 400.479153] __do_sys_finit_module+0xac/0x120
[ 400.479156] do_syscall_64+0x37/0x90
[ 400.479159] entry_SYSCALL_64_after_hwframe+0x63/0xcd
[ 400.479163]
-> #1 (reservation_ww_class_mutex){+.+.}-{3:3}:
[ 400.479167] __ww_mutex_lock.constprop.0+0xf1/0x1060
[ 400.479170] ww_mutex_lock+0x38/0xa0
[ 400.479173] check_whitelist+0x188/0x5c3 [i915]
[ 400.479348] check_whitelist_across_reset+0xba/0x3bc [i915]
[ 400.479524] live_reset_whitelist.cold+0x7c/0xd1 [i915]
[ 400.479694] __i915_subtests.cold+0x53/0xd5 [i915]
[ 400.479877] intel_workarounds_live_selftests+0x65/0x80 [i915]
[ 400.480028] run_pci_test+0x68/0x150 [test_i915]
[ 400.480034] live_workarounds+0x19/0x30 [test_i915]
[ 400.480039] kunit_try_run_case+0x4e/0x80
[ 400.480043] kunit_generic_run_threadfn_adapter+0x13/0x30
[ 400.480046] kthread+0xf2/0x120
[ 400.480049] ret_from_fork+0x1f/0x30
[ 400.480052]
-> #0 (&timeline->mutex/1){+.+.}-{3:3}:
[ 400.480056] __lock_acquire+0x16b7/0x28e0
[ 400.480060] lock_acquire+0xd1/0x2f0
[ 400.480062] __mutex_lock+0xca/0x8c0
[ 400.480065] live_hwsp_wrap+0x291/0x690 [i915]
[ 400.480212] __i915_subtests.cold+0x53/0xd5 [i915]
[ 400.480396] intel_timeline_live_selftests+0xbb/0xd0 [i915]
[ 400.480545] run_pci_test+0x68/0x150 [test_i915]
[ 400.480550] live_gt_timelines+0x19/0x30 [test_i915]
[ 400.480555] kunit_try_run_case+0x4e/0x80
[ 400.480558] kunit_generic_run_threadfn_adapter+0x13/0x30
[ 400.480561] kthread+0xf2/0x120
[ 400.480564] ret_from_fork+0x1f/0x30
[ 400.480566]
other info that might help us debug this:

[ 400.480569] Chain exists of:
&timeline->mutex/1 --> reservation_ww_class_mutex --> kernel_context

[ 400.480576] Possible unsafe locking scenario:

[ 400.480578] CPU0 CPU1
[ 400.480580] ---- ----
[ 400.480582] lock(kernel_context);
[ 400.480584] lock(reservation_ww_class_mutex);
[ 400.480587] lock(kernel_context);
[ 400.480590] lock(&timeline->mutex/1);
[ 400.480593]
*** DEADLOCK ***

[ 400.480595] 1 lock held by kunit_try_catch/2002:
[ 400.480597] #0: ffff888116cd9078 (kernel_context){+.+.}-{3:3}, at: i915_request_create+0x168/0x230 [i915]
[ 400.480759]
stack backtrace:
[ 400.480762] CPU: 0 PID: 2002 Comm: kunit_try_catch Tainted: G N 6.1.0-rc2-drm-990037e9984e+ #11
[ 400.480766] Hardware name: Intel Corporation Tiger Lake Client Platform/TigerLake U DDR4 SODIMM RVP, BIOS TGLSFWI1.R00.4073.A01.2102110036 02/11/2021
[ 400.480771] Call Trace:
[ 400.480773] <TASK>
[ 400.480775] dump_stack_lvl+0x6a/0x9f
[ 400.480779] check_noncircular+0x14c/0x170
[ 400.480783] __lock_acquire+0x16b7/0x28e0
[ 400.480787] lock_acquire+0xd1/0x2f0
[ 400.480789] ? live_hwsp_wrap+0x291/0x690 [i915]
[ 400.480938] __mutex_lock+0xca/0x8c0
[ 400.480941] ? live_hwsp_wrap+0x291/0x690 [i915]
[ 400.481086] ? live_hwsp_wrap+0x291/0x690 [i915]
[ 400.481230] ? live_hwsp_wrap+0x291/0x690 [i915]
[ 400.481374] live_hwsp_wrap+0x291/0x690 [i915]
[ 400.481517] ? kunit_try_catch_throw+0x20/0x20
[ 400.481520] __i915_subtests.cold+0x53/0xd5 [i915]
[ 400.481713] ? __i915_live_teardown+0x50/0x50 [i915]
[ 400.481898] ? __intel_gt_live_setup+0x60/0x60 [i915]
[ 400.482095] ? __intel_timeline_free+0x60/0x60 [i915]
[ 400.482274] ? kunit_try_catch_throw+0x20/0x20
[ 400.482277] intel_timeline_live_selftests+0xbb/0xd0 [i915]
[ 400.482452] run_pci_test+0x68/0x150 [test_i915]
[ 400.482460] live_gt_timelines+0x19/0x30 [test_i915]
[ 400.482466] kunit_try_run_case+0x4e/0x80
[ 400.482470] kunit_generic_run_threadfn_adapter+0x13/0x30
[ 400.482474] kthread+0xf2/0x120
[ 400.482477] ? kthread_complete_and_exit+0x20/0x20
[ 400.482482] ret_from_fork+0x1f/0x30
[ 400.482487] </TASK>
[ 400.483565] i915: Running intel_timeline_live_selftests/live_hwsp_read
[ 400.759423] rcs0: simulated 255 wraps
[ 400.860561] bcs0: simulated 255 wraps
[ 400.977662] vcs0: simulated 255 wraps
[ 401.094340] vcs1: simulated 255 wraps
[ 401.211137] vecs0: simulated 255 wraps
[ 401.247212] i915: Running intel_timeline_live_selftests/live_hwsp_rollover_kernel
[ 401.249829] i915: Running intel_timeline_live_selftests/live_hwsp_rollover_user
[ 401.271366] ok 5 - live_gt_timelines
[ 401.271738] i915: Running intel_context_live_selftests/live_context_size
[ 401.293251] i915: Running intel_context_live_selftests/live_active_context
[ 401.318254] i915: Running intel_context_live_selftests/live_remote_context
[ 401.344408] ok 6 - live_gt_contexts
[ 401.344798] i915: Running intel_lrc_live_selftests/live_lrc_layout
[ 401.345024] i915: Running intel_lrc_live_selftests/live_lrc_fixed
[ 401.345164] i915: Running intel_lrc_live_selftests/live_lrc_state
[ 401.362216] i915: Running intel_lrc_live_selftests/live_lrc_gpr
[ 401.392157] i915: Running intel_lrc_live_selftests/live_lrc_isolation
[ 401.495275] i915: Running intel_lrc_live_selftests/live_lrc_timestamp
[ 401.522173] i915: Running intel_lrc_live_selftests/live_lrc_garbage
[ 401.522194] i915: Running intel_lrc_live_selftests/live_pphwsp_runtime
[ 402.028730] rcs0: pphwsp runtime 479364012ns, average 58622293ns
[ 402.534520] bcs0: pphwsp runtime 195714584ns, average 76214ns
[ 403.037024] vcs0: pphwsp runtime 267333484ns, average 31694ns
[ 403.542426] vcs1: pphwsp runtime 248148756ns, average 46269ns
[ 404.048096] vecs0: pphwsp runtime 236339296ns, average 222600ns
[ 404.062233] i915: Running intel_lrc_live_selftests/live_lrc_indirect_ctx_bb
[ 404.084401] ok 7 - live_gt_lrc
[ 404.084710] i915: Running intel_mocs_live_selftests/live_mocs_kernel
[ 404.099257] i915: Running intel_mocs_live_selftests/live_mocs_clean
[ 404.123277] i915: Running intel_mocs_live_selftests/live_mocs_reset
[ 404.123631] i915 0000:00:02.0: [drm] Resetting rcs0 for mocs
[ 404.125376] i915 0000:00:02.0: [drm] Resetting rcs0 for mocs
[ 404.125882] i915 0000:00:02.0: [drm] Resetting chip for mocs
[ 404.126659] i915 0000:00:02.0: [drm] Resetting bcs0 for mocs
[ 404.127767] i915 0000:00:02.0: [drm] Resetting bcs0 for mocs
[ 404.127963] i915 0000:00:02.0: [drm] Resetting chip for mocs
[ 404.128735] i915 0000:00:02.0: [drm] Resetting vcs0 for mocs
[ 404.129807] i915 0000:00:02.0: [drm] Resetting vcs0 for mocs
[ 404.130028] i915 0000:00:02.0: [drm] Resetting chip for mocs
[ 404.130901] i915 0000:00:02.0: [drm] Resetting vcs1 for mocs
[ 404.132171] i915 0000:00:02.0: [drm] Resetting vcs1 for mocs
[ 404.132655] i915 0000:00:02.0: [drm] Resetting chip for mocs
[ 404.133745] i915 0000:00:02.0: [drm] Resetting vecs0 for mocs
[ 404.135328] i915 0000:00:02.0: [drm] Resetting vecs0 for mocs
[ 404.135918] i915 0000:00:02.0: [drm] Resetting chip for mocs
[ 404.158371] ok 8 - live_gt_mocs
[ 404.158708] i915: Running intel_gt_pm_live_selftests/live_gt_clocks
[ 404.164024] rcs0: TIMESTAMP 19249 cycles [1002553ns] in 1000425ns [19209 cycles], using CS clock frequency of 19200KHz
[ 404.169068] bcs0: TIMESTAMP 19229 cycles [1001511ns] in 1000129ns [19203 cycles], using CS clock frequency of 19200KHz
[ 404.174104] vcs0: TIMESTAMP 19237 cycles [1001928ns] in 1000328ns [19207 cycles], using CS clock frequency of 19200KHz
[ 404.179134] vcs1: TIMESTAMP 19234 cycles [1001771ns] in 1000100ns [19202 cycles], using CS clock frequency of 19200KHz
[ 404.184163] vecs0: TIMESTAMP 19234 cycles [1001771ns] in 1000126ns [19203 cycles], using CS clock frequency of 19200KHz
[ 404.184200] i915: Running intel_gt_pm_live_selftests/live_rc6_manual
[ 404.546138] GPU consumed 816180uW in RC0 and 203609uW in RC6
[ 404.546166] i915: Running intel_gt_pm_live_selftests/live_rps_clock_interval
[ 404.558110] rcs0: rps evaluation interval not ticking
[ 404.568099] i915: Running intel_gt_pm_live_selftests/live_rps_control
[ 405.296237] rcs0: range:[6:100MHz, 51:1350MHz] limit:[18:400MHz], 6:18 response 48876ns:49302ns
[ 406.023247] bcs0: range:[6:100MHz, 51:1350MHz] limit:[18:400MHz], 6:18 response 49111ns:49176ns
[ 406.750255] vcs0: range:[6:100MHz, 51:1350MHz] limit:[18:400MHz], 6:18 response 49391ns:49674ns
[ 407.477246] vcs1: range:[6:100MHz, 51:1350MHz] limit:[18:400MHz], 6:18 response 48930ns:49404ns
[ 408.200265] vecs0: range:[6:100MHz, 51:1350MHz] limit:[18:400MHz], 6:18 response 49045ns:50394ns
[ 408.207146] i915: Running intel_gt_pm_live_selftests/live_rps_frequency_cs
[ 408.299000] rcs0: min:10858KHz @ 100MHz, max:41423KHz @ 400MHz [95%]
[ 408.391000] bcs0: min:10864KHz @ 100MHz, max:42440KHz @ 400MHz [98%]
[ 408.483000] vcs0: min:10792KHz @ 100MHz, max:41926KHz @ 400MHz [97%]
[ 408.575000] vcs1: min:10810KHz @ 100MHz, max:42150KHz @ 400MHz [97%]
[ 408.667000] vecs0: min:10842KHz @ 100MHz, max:42055KHz @ 400MHz [97%]
[ 408.673253] i915: Running intel_gt_pm_live_selftests/live_rps_frequency_srm
[ 408.765000] rcs0: min:1975KHz @ 100MHz, max:5310KHz @ 400MHz [67%]
[ 408.856999] bcs0: min:1968KHz @ 100MHz, max:5301KHz @ 400MHz [67%]
[ 408.948999] vcs0: min:2007KHz @ 100MHz, max:5644KHz @ 400MHz [70%]
[ 409.040999] vcs1: min:1979KHz @ 100MHz, max:5534KHz @ 400MHz [70%]
[ 409.132998] vecs0: min:1971KHz @ 100MHz, max:5329KHz @ 400MHz [68%]
[ 409.140135] i915: Running intel_gt_pm_live_selftests/live_rps_power
[ 409.289056] rcs0: min:826mW @ 883MHz, max:1370mW @ 3533MHz
[ 409.438123] bcs0: min:857mW @ 883MHz, max:1103mW @ 3533MHz
[ 409.587115] vcs0: min:861mW @ 883MHz, max:1227mW @ 3533MHz
[ 409.736055] vcs1: min:824mW @ 883MHz, max:1213mW @ 3533MHz
[ 409.885060] vecs0: min:860mW @ 883MHz, max:1180mW @ 3533MHz
[ 409.891263] i915: Running intel_gt_pm_live_selftests/live_rps_interrupt
[ 409.891285] i915: Running intel_gt_pm_live_selftests/live_rps_dynamic
[ 409.891324] RPS has timer support
[ 410.427125] rcs0: dynamically reclocked to 24:400MHz while busy in 502129727ns, and 6:100MHz while idle in 32786357ns
[ 410.973124] bcs0: dynamically reclocked to 24:400MHz while busy in 507202384ns, and 6:100MHz while idle in 38207310ns
[ 411.499402] vcs0: dynamically reclocked to 24:400MHz while busy in 506289149ns, and 6:100MHz while idle in 19553670ns
[ 412.035126] vcs1: dynamically reclocked to 24:400MHz while busy in 504211376ns, and 6:100MHz while idle in 30994325ns
[ 412.565103] vecs0: dynamically reclocked to 24:400MHz while busy in 509906099ns, and 6:100MHz while idle in 19575224ns
[ 412.576269] i915: Running intel_gt_pm_live_selftests/live_gt_resume
[ 413.077831] ok 9 - live_gt_pm
[ 413.078173] i915: Running intel_heartbeat_live_selftests/live_idle_flush
[ 413.079302] i915: Running intel_heartbeat_live_selftests/live_idle_pulse
[ 413.080530] i915: Running intel_heartbeat_live_selftests/live_heartbeat_fast
[ 413.080547] i915 0000:00:02.0: [drm] rcs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.100996] rcs0: Heartbeat delay: 3989us [3981, 4425]
[ 413.101014] i915 0000:00:02.0: [drm] bcs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.120995] bcs0: Heartbeat delay: 3989us [3961, 3990]
[ 413.121011] i915 0000:00:02.0: [drm] vcs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.140997] vcs0: Heartbeat delay: 3989us [3965, 3991]
[ 413.141013] i915 0000:00:02.0: [drm] vcs1 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.160995] vcs1: Heartbeat delay: 3988us [3962, 3990]
[ 413.161011] i915 0000:00:02.0: [drm] vecs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.180995] vecs0: Heartbeat delay: 3988us [3965, 3989]
[ 413.181186] i915: Running intel_heartbeat_live_selftests/live_heartbeat_off
[ 413.181206] i915 0000:00:02.0: [drm] rcs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.181231] i915 0000:00:02.0: [drm] bcs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.181258] i915 0000:00:02.0: [drm] vcs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.181282] i915 0000:00:02.0: [drm] vcs1 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.181306] i915 0000:00:02.0: [drm] vecs0 heartbeat interval adjusted to a non-default value which may cause engine resets to target innocent contexts!
[ 413.182041] ok 10 - live_gt_heartbeat
[ 413.182263] i915: Running i915_request_live_selftests/live_nop_request
[ 413.684506] Request latencies on rcs0: 1 = 193278ns, 631 = 14517ns
[ 414.187056] Request latencies on bcs0: 1 = 58198ns, 1103 = 5363ns
[ 414.691635] Request latencies on vcs0: 1 = 208875ns, 1103 = 5284ns
[ 415.193970] Request latencies on vcs1: 1 = 100363ns, 1091 = 5276ns
[ 415.694286] Request latencies on vecs0: 1 = 100734ns, 1093 = 5386ns
[ 415.694296] i915: Running i915_request_live_selftests/live_all_engines
[ 415.704108] i915: Running i915_request_live_selftests/live_sequential_engines
[ 415.724264] i915: Running i915_request_live_selftests/live_parallel_engines
[ 416.225005] vecs0: 9164 request + sync
[ 416.225017] vcs0: 9272 request + sync
[ 416.225018] bcs0: 10629 request + sync
[ 416.225019] rcs0: 4249 request + sync
[ 416.225086] vcs1: 8231 request + sync
[ 416.725993] vcs1: 42724 requests
[ 416.725993] vecs0: 49770 requests
[ 416.725993] bcs0: 43715 requests
[ 416.725999] rcs0: 34664 requests
[ 416.726005] vcs0: 30252 requests
[ 416.740332] i915: Running i915_request_live_selftests/live_empty_request
[ 417.249170] Batch latencies on rcs0: 1 = 100180ns, 601 = 16439ns
[ 417.751340] Batch latencies on bcs0: 1 = 52030ns, 1051 = 5869ns
[ 418.254066] Batch latencies on vcs0: 1 = 50862ns, 1051 = 5842ns
[ 418.757832] Batch latencies on vcs1: 1 = 83003ns, 1051 = 5873ns
[ 419.260333] Batch latencies on vecs0: 1 = 88003ns, 1051 = 5793ns
[ 419.266226] i915: Running i915_request_live_selftests/live_cancel_request
[ 419.271266] i915 0000:00:02.0: [drm] Resetting rcs0 for preemption time out
[ 419.271373] i915 0000:00:02.0: [drm] GPU HANG: ecode 12:1:e75ffefe
[ 419.378400] i915 0000:00:02.0: [drm] Resetting bcs0 for preemption time out
[ 419.378519] i915 0000:00:02.0: [drm] GPU HANG: ecode 12:2:10000001
[ 419.385222] i915 0000:00:02.0: [drm] Resetting vcs0 for preemption time out
[ 419.385313] i915 0000:00:02.0: [drm] GPU HANG: ecode 12:4:277ffefe
[ 419.391308] i915 0000:00:02.0: [drm] Resetting vcs1 for preemption time out
[ 419.391405] i915 0000:00:02.0: [drm] GPU HANG: ecode 12:4:277ffefe
[ 419.397223] i915 0000:00:02.0: [drm] Resetting vecs0 for preemption time out
[ 419.397276] i915 0000:00:02.0: [drm] GPU HANG: ecode 12:8:277ffefe
[ 419.423272] i915: Running i915_request_live_selftests/live_breadcrumbs_smoketest
[ 420.105820] Completed 1282 waits for 44096 fences across 5 engines and 8 cpus
[ 420.115171] ok 11 - live_requests
[ 420.115246] i915: Running intel_migrate_live_selftests/live_migrate_copy
[ 420.531252] i915: Running intel_migrate_live_selftests/live_migrate_clear
[ 420.829122] i915: Running intel_migrate_live_selftests/thread_migrate_copy
[ 420.922498] i915: Running intel_migrate_live_selftests/thread_migrate_clear
[ 421.020675] i915: Running intel_migrate_live_selftests/thread_global_copy
[ 421.110435] i915: Running intel_migrate_live_selftests/thread_global_clear
[ 421.184091] ok 12 - live_migrate
[ 421.184170] i915: Running i915_active_live_selftests/live_active_wait
[ 421.185033] i915: Running i915_active_live_selftests/live_active_retire
[ 421.185610] i915: Running i915_active_live_selftests/live_active_barrier
[ 421.185976] ok 13 - live_active
[ 421.186102] i915: Running i915_gem_object_live_selftests/igt_gem_huge
[ 421.388389] ok 14 - live_objects
[ 421.388633] i915: Running i915_gem_mman_live_selftests/igt_partial_tiling
[ 421.906998] check_partial_mappings: timed out after tiling=0 stride=0
[ 422.408024] check_partial_mappings: timed out after tiling=1 stride=262144
[ 422.909049] check_partial_mappings: timed out after tiling=2 stride=262144
[ 422.928131] i915: Running i915_gem_mman_live_selftests/igt_smoke_tiling
[ 423.429058] igt_smoke_tiling: Completed 4952 trials
[ 423.503189] i915: Running i915_gem_mman_live_selftests/igt_mmap_offset_exhaustion
[ 423.523154] i915: Running i915_gem_mman_live_selftests/igt_mmap
[ 423.523363] BUG: kernel NULL pointer dereference, address: 00000000000000e8
[ 423.523367] #PF: supervisor write access in kernel mode
[ 423.523370] #PF: error_code(0x0002) - not-present page
[ 423.523373] PGD 0 P4D 0
[ 423.523375] Oops: 0002 [#1] PREEMPT SMP NOPTI
[ 423.523379] CPU: 5 PID: 2157 Comm: kunit_try_catch Tainted: G N 6.1.0-rc2-drm-990037e9984e+ #11
[ 423.523384] Hardware name: Intel Corporation Tiger Lake Client Platform/TigerLake U DDR4 SODIMM RVP, BIOS TGLSFWI1.R00.4073.A01.2102110036 02/11/2021
[ 423.523388] RIP: 0010:down_write_killable+0x50/0x110
[ 423.523394] Code: 24 10 45 31 c9 31 c9 41 b8 01 00 00 00 31 d2 31 f6 48 89 ef e8 e1 74 4a ff bf 01 00 00 00 e8 87 d6 46 ff 31 c0 ba 01 00 00 00 <f0> 48 0f b1 13 0f 94 c0 5a 84 c0 74 62 8b 05 49 12 e4 00 85 c0 74
[ 423.523401] RSP: 0018:ffffc90000823c68 EFLAGS: 00010246
[ 423.523404] RAX: 0000000000000000 RBX: 00000000000000e8 RCX: 0000000000000000
[ 423.523407] RDX: 0000000000000001 RSI: ffffffff81c94fc9 RDI: ffffffff81c94fc9
[ 423.523410] RBP: 0000000000000158 R08: 0000000000000001 R09: 0000000000000000
[ 423.523413] R10: 0000000000000000 R11: ffff88849d52e348 R12: 0000000000000002
[ 423.523416] R13: 0000000000000001 R14: 0000000000100000 R15: 00000000000000e8
[ 423.523419] FS: 0000000000000000(0000) GS:ffff88849fa80000(0000) knlGS:0000000000000000
[ 423.523422] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 423.523425] CR2: 00000000000000e8 CR3: 0000000002812005 CR4: 0000000000770ee0
[ 423.523428] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 423.523431] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 423.523433] PKRU: 55555554
[ 423.523435] Call Trace:
[ 423.523437] <TASK>
[ 423.523439] ? vm_mmap_pgoff+0x78/0x150
[ 423.523445] vm_mmap_pgoff+0x78/0x150
[ 423.523449] igt_mmap_offset+0x133/0x1e0 [i915]
[ 423.523672] __igt_mmap+0xfe/0x680 [i915]
[ 423.523826] ? __i915_gem_object_create_user_ext+0x49c/0x550 [i915]
[ 423.523969] igt_mmap+0xd8/0x290 [i915]
[ 423.524135] ? __trace_bprintk+0x8c/0xa0
[ 423.524141] ? kunit_try_catch_throw+0x20/0x20
[ 423.524146] __i915_subtests.cold+0x53/0xd5 [i915]
[ 423.524357] ? __i915_nop_teardown+0x20/0x20 [i915]
[ 423.524533] ? __i915_live_setup+0x60/0x60 [i915]
[ 423.524725] ? singleton_release+0x40/0x40 [i915]
[ 423.524933] ? kunit_try_catch_throw+0x20/0x20
[ 423.524938] i915_gem_mman_live_selftests+0x37/0x50 [i915]
[ 423.525145] run_pci_test+0x68/0x150 [test_i915]
[ 423.525153] ? lock_release+0x22d/0x2f0
[ 423.525158] ? _raw_spin_unlock_irqrestore+0x53/0x80
[ 423.525164] live_mman+0x19/0x30 [test_i915]
[ 423.525171] kunit_try_run_case+0x4e/0x80
[ 423.525175] kunit_generic_run_threadfn_adapter+0x13/0x30
[ 423.525180] kthread+0xf2/0x120
[ 423.525184] ? kthread_complete_and_exit+0x20/0x20
[ 423.525189] ret_from_fork+0x1f/0x30
[ 423.525196] </TASK>
[ 423.525198] Modules linked in: test_i915 mei_hdcp snd_hda_codec_hdmi x86_pkg_temp_thermal coretemp snd_hda_intel snd_intel_dspcfg snd_hda_codec kvm_intel snd_hwdep snd_hda_core mei_me kvm irqbypass wmi_bmof snd_pcm i2c_i801 mei i2c_smbus intel_lpss_pci crct10dif_pclmul crc32_pclmul ghash_clmulni_intel i915 prime_numbers drm_buddy e1000e drm_display_helper ptp pps_core drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm video wmi fuse
[ 423.525240] CR2: 00000000000000e8
[ 423.525243] ---[ end trace 0000000000000000 ]---
[ 423.759155] RIP: 0010:down_write_killable+0x50/0x110
[ 423.759205] Code: 24 10 45 31 c9 31 c9 41 b8 01 00 00 00 31 d2 31 f6 48 89 ef e8 e1 74 4a ff bf 01 00 00 00 e8 87 d6 46 ff 31 c0 ba 01 00 00 00 <f0> 48 0f b1 13 0f 94 c0 5a 84 c0 74 62 8b 05 49 12 e4 00 85 c0 74
[ 423.759213] RSP: 0018:ffffc90000823c68 EFLAGS: 00010246
[ 423.759216] RAX: 0000000000000000 RBX: 00000000000000e8 RCX: 0000000000000000
[ 423.759220] RDX: 0000000000000001 RSI: ffffffff81c94fc9 RDI: ffffffff81c94fc9
[ 423.759222] RBP: 0000000000000158 R08: 0000000000000001 R09: 0000000000000000
[ 423.759225] R10: 0000000000000000 R11: ffff88849d52e348 R12: 0000000000000002
[ 423.759228] R13: 0000000000000001 R14: 0000000000100000 R15: 00000000000000e8
[ 423.759231] FS: 0000000000000000(0000) GS:ffff88849fa80000(0000) knlGS:0000000000000000
[ 423.759235] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 423.759237] CR2: 00000000000000e8 CR3: 0000000121d76004 CR4: 0000000000770ee0
[ 423.759240] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 423.759243] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 423.759246] PKRU: 55555554
[ 423.759248] note: kunit_try_catch[2157] exited with preempt_count 1
[ 726.442175] # live_mman: try timed out
[ 726.442202] stack segment: 0000 [#2] PREEMPT SMP NOPTI
[ 726.442216] CPU: 0 PID: 1854 Comm: i915_selftest Tainted: G D N 6.1.0-rc2-drm-990037e9984e+ #11
[ 726.442232] Hardware name: Intel Corporation Tiger Lake Client Platform/TigerLake U DDR4 SODIMM RVP, BIOS TGLSFWI1.R00.4073.A01.2102110036 02/11/2021
[ 726.442248] RIP: 0010:kthread_stop+0x5a/0x270
[ 726.442264] Code: 00 f0 0f c1 43 28 85 c0 0f 84 19 02 00 00 8d 50 01 09 c2 0f 88 de 01 00 00 f6 43 2e 20 0f 84 eb 01 00 00 48 8b ab 58 06 00 00 <f0> 80 4d 00 02 48 89 df e8 e9 f1 ff ff f0 80 4b 02 02 48 89 df e8
[ 726.442286] RSP: 0018:ffffc90004493a00 EFLAGS: 00010202
[ 726.442298] RAX: 000000006b6b6b6b RBX: ffff88810db30040 RCX: 0000000000000000
[ 726.442309] RDX: 000000006b6b6b6f RSI: ffffffff8253fb3d RDI: ffff88810db30040
[ 726.442319] RBP: 6b6b6b6b6b6b6b6b R08: 00000000fffeffff R09: 00000000fffeffff
[ 726.442329] R10: ffff88849f080000 R11: ffff88849f080000 R12: ffff88810db30068
[ 726.442338] R13: ffffffffa0320680 R14: ffffffffa0320680 R15: ffffffffa0320af0
[ 726.442348] FS: 00007faa5d14ba80(0000) GS:ffff88849f800000(0000) knlGS:0000000000000000
[ 726.442361] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 726.442370] CR2: 00007f0d3c010c58 CR3: 000000011570c005 CR4: 0000000000770ef0
[ 726.442380] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 726.442390] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 726.442400] PKRU: 55555554
[ 726.442405] Call Trace:
[ 726.442411] <TASK>
[ 726.442419] kunit_try_catch_run.cold+0x67/0x97
[ 726.442439] kunit_run_case_catch_errors+0x73/0xba
[ 726.442451] kunit_run_tests.cold+0x1b1/0x555
[ 726.442465] ? kunit_catch_run_case+0x40/0x40
[ 726.442477] ? kunit_module_notify+0x50/0x50
[ 726.442508] __kunit_test_suites_init+0x48/0x60
[ 726.442519] kunit_module_notify+0x3d/0x50
[ 726.442528] notifier_call_chain+0x43/0xb0
[ 726.442543] blocking_notifier_call_chain+0x41/0x60
[ 726.442557] do_init_module+0x9d/0x210
[ 726.442569] __do_sys_finit_module+0xac/0x120
[ 726.442586] do_syscall_64+0x37/0x90
[ 726.442598] entry_SYSCALL_64_after_hwframe+0x63/0xcd
[ 726.442612] RIP: 0033:0x7faa5f10af3d
[ 726.442622] Code: 5d c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d b3 ce 0e 00 f7 d8 64 89 01 48
[ 726.442643] RSP: 002b:00007ffd26206128 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[ 726.442656] RAX: ffffffffffffffda RBX: 0000000001356880 RCX: 00007faa5f10af3d
[ 726.442666] RDX: 0000000000000000 RSI: 00007faa5f21843c RDI: 0000000000000004
[ 726.442675] RBP: 00007faa5f21843c R08: 0000000000000000 R09: 00007ffd26206250
[ 726.442685] R10: 0000000000000004 R11: 0000000000000246 R12: 0000000000000000
[ 726.442694] R13: 0000000001357410 R14: 0000000000000000 R15: 000000000135a760
[ 726.442710] </TASK>
[ 726.442715] Modules linked in: test_i915 mei_hdcp snd_hda_codec_hdmi x86_pkg_temp_thermal coretemp snd_hda_intel snd_intel_dspcfg snd_hda_codec kvm_intel snd_hwdep snd_hda_core mei_me kvm irqbypass wmi_bmof snd_pcm i2c_i801 mei i2c_smbus intel_lpss_pci crct10dif_pclmul crc32_pclmul ghash_clmulni_intel i915 prime_numbers drm_buddy e1000e drm_display_helper ptp pps_core drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm video wmi fuse
[ 726.442811] ---[ end trace 0000000000000000 ]---
[ 726.651075] RIP: 0010:down_write_killable+0x50/0x110
[ 726.651097] Code: 24 10 45 31 c9 31 c9 41 b8 01 00 00 00 31 d2 31 f6 48 89 ef e8 e1 74 4a ff bf 01 00 00 00 e8 87 d6 46 ff 31 c0 ba 01 00 00 00 <f0> 48 0f b1 13 0f 94 c0 5a 84 c0 74 62 8b 05 49 12 e4 00 85 c0 74
[ 726.651104] RSP: 0018:ffffc90000823c68 EFLAGS: 00010246
[ 726.651107] RAX: 0000000000000000 RBX: 00000000000000e8 RCX: 0000000000000000
[ 726.651110] RDX: 0000000000000001 RSI: ffffffff81c94fc9 RDI: ffffffff81c94fc9
[ 726.651113] RBP: 0000000000000158 R08: 0000000000000001 R09: 0000000000000000
[ 726.651115] R10: 0000000000000000 R11: ffff88849d52e348 R12: 0000000000000002
[ 726.651118] R13: 0000000000000001 R14: 0000000000100000 R15: 00000000000000e8
[ 726.651121] FS: 00007faa5d14ba80(0000) GS:ffff88849f800000(0000) knlGS:0000000000000000
[ 726.651124] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 726.651127] CR2: 00007f0d3c010c58 CR3: 000000011570c005 CR4: 0000000000770ef0
[ 726.651129] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 726.651132] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 726.651134] PKRU: 55555554

[Mauro Carvalho Chehab]

On Thu, 3 Nov 2022 10:48:40 +0100

Mauro Carvalho Chehab <mauro....@linux.intel.com> wrote:

> On Sun, 28 Aug 2022 21:09:19 -0300
> Isabella Basso <isab...@riseup.net> wrote:
>
> > This adds functions for both executing the tests as well as parsing (K)TAP
> > kmsg output, as per the KTAP spec [1].
> >
> > [1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html
> >
> > Signed-off-by: Isabella Basso <isab...@riseup.net>
>
> Hi Isabella,
>
> I'm doing some tests here with my i915 KUnit patch series.
>
> There's a problem with the way it is currently parsing the KTAP logs on
> IGT. It sounds that it is parsing the data only at the end, and not as
> they arrive. That's bad, as if something goes wrong, the previously
> reported data is still useful.
>
> Also, when there's a crash, the IGT process is getting segmentation
> fault. So, the end result is that nothing is actually reported.
>
> $ sudo ./build/tests/i915_selftest
> IGT-Version: 1.26-gbab20eb65 (x86_64) (Linux: 6.1.0-rc2-drm-990037e9984e+ x86_64)
> Segmentation fault (core dumped)

Another issue related to KTAP parsing: this is the output before
the KUnit patch, which is used by IGT CI to check the test results, for
i915 mock selftest:

<snip>
IGT-Version: 1.26-gbab20eb65 (x86_64) (Linux: 6.1.0-rc2-drm-8dacd9299fcc+ x86_64)
process 659 (alsactl) is using audio device. Should be terminated.
Starting subtest: mock
Starting dynamic subtest: sanitycheck
Dynamic subtest sanitycheck: SUCCESS (0.648s)
Starting dynamic subtest: shmem
Dynamic subtest shmem: SUCCESS (0.557s)
Starting dynamic subtest: fence
Dynamic subtest fence: SUCCESS (8.078s)
Starting dynamic subtest: scatterlist
Dynamic subtest scatterlist: SUCCESS (1.531s)
Starting dynamic subtest: syncmap
Dynamic subtest syncmap: SUCCESS (2.875s)
Starting dynamic subtest: uncore
Dynamic subtest uncore: SUCCESS (0.525s)
Starting dynamic subtest: ring
Dynamic subtest ring: SUCCESS (0.529s)
Starting dynamic subtest: engine
Dynamic subtest engine: SUCCESS (0.527s)
Starting dynamic subtest: timelines
Dynamic subtest timelines: SUCCESS (4.177s)
Starting dynamic subtest: requests
Dynamic subtest requests: SUCCESS (3.561s)
Starting dynamic subtest: objects
Dynamic subtest objects: SUCCESS (0.596s)
Starting dynamic subtest: phys
Dynamic subtest phys: SUCCESS (0.602s)
Starting dynamic subtest: dmabuf
Dynamic subtest dmabuf: SUCCESS (0.605s)
Starting dynamic subtest: vma
Dynamic subtest vma: SUCCESS (9.724s)
Starting dynamic subtest: evict
Dynamic subtest evict: SUCCESS (1.660s)
Starting dynamic subtest: gtt
Dynamic subtest gtt: SUCCESS (3.309s)
Starting dynamic subtest: hugepages
Dynamic subtest hugepages: SUCCESS (1.665s)
Starting dynamic subtest: memory_region
Dynamic subtest memory_region: SUCCESS (2.789s)
Subtest mock: SUCCESS (43.961s)
</snip>

This is the logs after your patch:

<snip>
Missing test version string
Executing 18 tests in: i915 mock selftests
kmsg> 1..18
kmsg> i915: i915_mock_sanitycheck() - ok!
kmsg> ok 1 - mock_sanitycheck
kmsg> i915: Running shmem_utils_mock_selftests/igt_shmem_basic
kmsg> ok 2 - mock_shmem
kmsg> i915: Running i915_sw_fence_mock_selftests/test_self
kmsg> i915: Running i915_sw_fence_mock_selftests/test_dag
kmsg> i915: Running i915_sw_fence_mock_selftests/test_AB
kmsg> i915: Running i915_sw_fence_mock_selftests/test_ABC
kmsg> i915: Running i915_sw_fence_mock_selftests/test_AB_C
kmsg> i915: Running i915_sw_fence_mock_selftests/test_C_AB
kmsg> i915: Running i915_sw_fence_mock_selftests/test_chain
kmsg> i915: Running i915_sw_fence_mock_selftests/test_ipc
kmsg> i915: Running i915_sw_fence_mock_selftests/test_timer
kmsg> i915: Running i915_sw_fence_mock_selftests/test_dma_fence
kmsg> Asynchronous wait on fence mock:mock:0 timed out (hint:fence_notify [i915])
kmsg> ok 3 - mock_fence
kmsg> i915: Running scatterlist_mock_selftests/igt_sg_alloc
kmsg> sg_alloc_table timed out
kmsg> i915: Running scatterlist_mock_selftests/igt_sg_trim
kmsg> i915_sg_trim timed out
kmsg> ok 4 - mock_scatterlist
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_init
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_one
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_join_above
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_join_below
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_neighbours
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_compact
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_random
kmsg> ok 5 - mock_syncmap
kmsg> ok 6 - mock_uncore
kmsg> i915: Running intel_ring_mock_selftests/igt_ring_direction
kmsg> ok 7 - mock_ring
kmsg> i915: Running intel_engine_cs_mock_selftests/intel_mmio_bases_check
kmsg> ok 8 - mock_engine
kmsg> i915: Running intel_timeline_mock_selftests/mock_hwsp_freelist
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running intel_timeline_mock_selftests/igt_sync
kmsg> i915: Running intel_timeline_mock_selftests/bench_sync
kmsg> bench_sync: 44045 random insertions, 2288ns/insert
kmsg> bench_sync: 44045 random lookups, 80ns/lookup
kmsg> bench_sync: 877617 in-order insertions, 114ns/insert
kmsg> bench_sync: 877617 in-order lookups, 3ns/lookup
kmsg> bench_sync: 6357870 repeated insert/lookups, 10ns/op
kmsg> bench_sync: 19942183 cyclic/1 insert/lookups, 5ns/op
kmsg> bench_sync: 19353937 cyclic/2 insert/lookups, 5ns/op
kmsg> bench_sync: 16969941 cyclic/3 insert/lookups, 5ns/op
kmsg> bench_sync: 14438533 cyclic/5 insert/lookups, 6ns/op
kmsg> bench_sync: 13418112 cyclic/8 insert/lookups, 7ns/op
kmsg> bench_sync: 9257200 cyclic/13 insert/lookups, 10ns/op
kmsg> bench_sync: 53636 cyclic/21 insert/lookups, 1877ns/op
kmsg> ok 9 - mock_timelines
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_request_mock_selftests/igt_add_request
kmsg> i915: Running i915_request_mock_selftests/igt_wait_request
kmsg> i915: Running i915_request_mock_selftests/igt_fence_wait
kmsg> i915: Running i915_request_mock_selftests/igt_request_rewind
kmsg> i915: Running i915_request_mock_selftests/mock_breadcrumbs_smoketest
kmsg> Completed 92 waits for 49042 fence across 8 cpus
kmsg> ok 10 - mock_requests
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_object_mock_selftests/igt_gem_object
kmsg> ok 11 - mock_objects
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_phys_mock_selftests/mock_phys_object
kmsg> ok 12 - mock_phys
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_export
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import_self
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import_ownership
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_export_vmap
kmsg> ok 13 - mock_dmabuf
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_create
kmsg> igt_vma_create timed out: after 31 objects in 23 contexts
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_pin1
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_rotate_remap
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_partial
kmsg> ok 14 - mock_vma
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_something
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_for_vma
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_for_cache_color
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_vm
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_overcommit
kmsg> ok 15 - mock_evict
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_drunk
kmsg> drunk_hole timed out after 31635/524288
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_walk
kmsg> walk_hole timed out at 812f000
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_pot
kmsg> pot_hole timed out after 19/33
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_fill
kmsg> fill_hole timed out (npages=1, prime=199)
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_gtt_reserve
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_gtt_insert
kmsg> ok 16 - mock_gtt
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_exhaust_device_supported_pages
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_memory_region_huge_pages
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_misaligned_dma
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_huge_fill
kmsg> igt_mock_ppgtt_huge_fill timed out at size 43986944
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_64K
kmsg> ok 17 - mock_hugepages
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_reserve
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_fill
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_contiguous
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_splintered_region
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_max_segment
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_io_size
kmsg> igt_mock_io_size with ps=10000, io_size=10000000, total=cf110000
kmsg> igt_mock_io_size mappable theft=(0MiB/256MiB), total=3313MiB
kmsg> ok 18 - mock_memory_region
kmsg> # i915 mock selftests: pass:18 fail:0 skip:0 total:18
kmsg> # Totals: pass:18 fail:0 skip:0 total:18
kmsg> ok 1 - i915 mock selftests
SUCCESS (29.259s)
</snip>

Basically, the current output will break CI reports presented at:
https://intel-gfx-ci.01.org/tree/drm-tip/bat-all.html?testfilter=selftest

The IGT output after your change should be similar to what we had
before, e. g. each test should output SUCCESS/FAIL/SKIP (plus the
final result of all tests at the suite).

any other non-KTAP messages from dmesg should be ignored, as, if
needed, those can be obtained later, as IGT runs on bare metal,
and not inside a VM.

Regards,
Mauro

[Petri Latvala]

That should not be done manually though. Only with igt_subtest /
igt_dynamic blocks.

--
Petri Latvala

[Mauro Carvalho Chehab]

On Thu, 3 Nov 2022 10:48:40 +0100
Mauro Carvalho Chehab <mauro....@linux.intel.com> wrote:

> On Sun, 28 Aug 2022 21:09:19 -0300
> Isabella Basso <isab...@riseup.net> wrote:
>
> > This adds functions for both executing the tests as well as parsing (K)TAP
> > kmsg output, as per the KTAP spec [1].
> >
> > [1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html
> >
> > Signed-off-by: Isabella Basso <isab...@riseup.net>
>
> Hi Isabella,
>
> I'm doing some tests here with my i915 KUnit patch series.
>
> There's a problem with the way it is currently parsing the KTAP logs on
> IGT. It sounds that it is parsing the data only at the end, and not as
> they arrive. That's bad, as if something goes wrong, the previously
> reported data is still useful.
>
> Also, when there's a crash, the IGT process is getting segmentation
> fault. So, the end result is that nothing is actually reported.
>
> $ sudo ./build/tests/i915_selftest
> IGT-Version: 1.26-gbab20eb65 (x86_64) (Linux: 6.1.0-rc2-drm-990037e9984e+ x86_64)
> Segmentation fault (core dumped)
>
> However, the logs are there (see enclosed). In this specific case, there
> was a GPU hang while running one of the tests on a real hardware, which
> is something that it is actually expected at development time.

Btw, if you want to test it, the patches I'm using are at:
https://patchwork.freedesktop.org/series/110483/

The latest patch there is a workaround that fixes the issue. So, if you
apply patches 1-7 only, skipping (or reverting) patch 8, you'll be able
to reproduce the Kernel crash (which seems to be caused by the way KUnit
is initialized).

Regards,
Mauro

[Janusz Krzysztofik]

Hi Isabella,

On Monday, 19 September 2022 22:55:44 CET Isabella Basso wrote:
> Hi, Janusz,
>
> > Am 09/09/2022 um 12:18 PM schrieb Janusz Krzysztofik <janusz.kr...@linux.intel.com>:
> >

> > ...

> >
> > Anyway, related to my comment about naming that function a parser, I think the
> > best approach would be for that parser to return a generic set of results from
> > kunit execution, then we could feed that data into an IGT specific handler
> > that would convert them to IGT results (SUCCESS, FAIL, or SKIP) as if returned
> > by a set of IGT dynamic subtests.
>
> That sounds like a good idea to me, I might take some extra time before v3 to
> do that, though.

Were you able to make any progress? Do you need any help?

Thanks,
Janusz

[Isabella Basso]

Hi, Janusz,

I’ve already handled most common cases but I still have to address Chehab’s comments — specifically in what concerns crashes. I’ve been doing most of the development by myself as GSoC has ended so I’m taking my time on this.

My most up-to-date work is available at [1], so if you have any suggestions as to what might be done I’d love to hear them before sending out v3 to the mailing list.

[1] - https://gitlab.freedesktop.org/isinyaaa/igt-gpu-tools/-/merge_requests/1

Cheers,
--
Isabella Basso

> Thanks,
> Janusz
>
>

> --
> You received this message because you are subscribed to the Google Groups "KUnit Development" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to kunit-dev+...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/kunit-dev/7621786.lvqk35OSZv%40jkrzyszt-mobl1.ger.corp.intel.com.

[Janusz Krzysztofik]

Hi Isabella,

On Friday, 10 February 2023 17:55:34 CET Isabella Basso wrote:
> Hi, Janusz,
>
> > Am 2023-02-10 um 11:56 AM schrieb Janusz Krzysztofik <janusz.kr...@linux.intel.com>:
> >
> > Hi Isabella,
> >
> > On Monday, 19 September 2022 22:55:44 CET Isabella Basso wrote:
> >> Hi, Janusz,
> >>
> >>> Am 09/09/2022 um 12:18 PM schrieb Janusz Krzysztofik <janusz.kr...@linux.intel.com>:
> >>>
> >>> ...
> >>>
> >>> Anyway, related to my comment about naming that function a parser, I think the
> >>> best approach would be for that parser to return a generic set of results from
> >>> kunit execution, then we could feed that data into an IGT specific handler
> >>> that would convert them to IGT results (SUCCESS, FAIL, or SKIP) as if returned
> >>> by a set of IGT dynamic subtests.
> >>
> >> That sounds like a good idea to me, I might take some extra time before v3 to
> >> do that, though.
> >
> > Were you able to make any progress? Do you need any help?
>
> I’ve already handled most common cases but I still have to address Chehab’s comments — specifically in what concerns crashes. I’ve been doing most of the development by myself as GSoC has ended so I’m taking my time on this.
>
> My most up-to-date work is available at [1], so if you have any suggestions as to what might be done I’d love to hear them before sending out v3 to the mailing list.
>
> [1] - https://gitlab.freedesktop.org/isinyaaa/igt-gpu-tools/-/merge_requests/1

Thanks for pointing me to that merge request, it's great to know there is
some progress. I've just had a look and I can see you are now working on some
comments from Maria and Tales. I've requested to be notified on new posts to
that merge request so I hope to review your next update when available.

As soon as you resolve issues and feel comfortable with sharing your work,
please submit your changes to the igt-dev list to give them a try on our CI
system.

Thanks,
Janusz