[PATCH igt 1/2] lib: Export kmsg()

[PATCH igt 1/2] lib: Export kmsg()

[Chris Wilson]

Export the kmsg() function for use by tests to write into the kernel
message log, useful for tests to inline their progress with kernel error
messages.

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
---
 lib/igt_core.c | 20 ++++++--------------
 lib/igt_core.h | 17 +++++++++++++++++
 2 files changed, 23 insertions(+), 14 deletions(-)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 777687b5f..cec5f066b 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -385,16 +385,7 @@ void igt_log_buffer_inspect(igt_buffer_log_handler_t check, void *data)
 	pthread_mutex_unlock(&log_buffer_mutex);
 }
 
-__attribute__((format(printf, 1, 2)))
-static void kmsg(const char *format, ...)
-#define KERN_EMER	"<0>"
-#define KERN_ALERT	"<1>"
-#define KERN_CRIT	"<2>"
-#define KERN_ERR	"<3>"
-#define KERN_WARNING	"<4>"
-#define KERN_NOTICE	"<5>"
-#define KERN_INFO	"<6>"
-#define KERN_DEBUG	"<7>"
+void igt_kmsg(const char *format, ...)
 {
 	va_list ap;
 	FILE *file;
@@ -810,7 +801,7 @@ out:
 
 	if (!list_subtests) {
 		kick_fbcon(false);
-		kmsg(KERN_INFO "[IGT] %s: executing\n", command_str);
+		igt_kmsg(KMSG_INFO "%s: executing\n", command_str);
 		print_version();
 
 		sync();
@@ -937,7 +928,8 @@ bool __igt_run_subtest(const char *subtest_name)
 		return false;
 	}
 
-	kmsg(KERN_INFO "[IGT] %s: starting subtest %s\n", command_str, subtest_name);
+	igt_kmsg(KMSG_INFO "%s: starting subtest %s\n",
+		 command_str, subtest_name);
 	igt_debug("Starting subtest: %s\n", subtest_name);
 
 	_igt_log_buffer_reset();
@@ -1444,8 +1436,8 @@ void igt_exit(void)
 	}
 
 	if (command_str)
-		kmsg(KERN_INFO "[IGT] %s: exiting, ret=%d\n",
-		     command_str, igt_exitcode);
+		igt_kmsg(KMSG_INFO "%s: exiting, ret=%d\n",
+			 command_str, igt_exitcode);
 	igt_debug("Exiting with status code %d\n", igt_exitcode);
 
 	for (int c = 0; c < num_test_children; c++)
diff --git a/lib/igt_core.h b/lib/igt_core.h
index f8543d658..7af2b4c10 100644
--- a/lib/igt_core.h
+++ b/lib/igt_core.h
@@ -932,4 +932,21 @@ int igt_system_quiet(const char *command);
 		free(buf); \
 	} while (0)
 
+/**
+ * igt_kmsg:
+ * @format: printf-style format string with optional args
+ *
+ * Writes a message into the kernel log file (/dev/kmsg).
+ */
+__attribute__((format(printf, 1, 2)))
+void igt_kmsg(const char *format, ...);
+#define KMSG_EMER	"<0>[IGT] "
+#define KMSG_ALERT	"<1>[IGT] "
+#define KMSG_CRIT	"<2>[IGT] "
+#define KMSG_ERR	"<3>[IGT] "
+#define KMSG_WARNING	"<4>[IGT] "
+#define KMSG_NOTICE	"<5>[IGT] "
+#define KMSG_INFO	"<6>[IGT] "
+#define KMSG_DEBUG	"<7>[IGT] "
+
 #endif /* IGT_CORE_H */
-- 
2.15.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

[PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Chris Wilson]

When tracking down the cause of a particular kernel warning, knowing
which file it is associated with can be a big clue. So write the
filename into the kernel message log prior to opening it.

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
---
 tests/debugfs_test.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tests/debugfs_test.c b/tests/debugfs_test.c
index 268d6e78f..2e87e4420 100644
--- a/tests/debugfs_test.c
+++ b/tests/debugfs_test.c
@@ -61,8 +61,9 @@ static void read_and_discard_sysfs_entries(int path_fd, int indent)
 			int sub_fd;
 			ssize_t ret;
 
-			igt_set_timeout(5, "reading sysfs entry");
+			igt_kmsg(KMSG_DEBUG "Reading file \"%s\"\n", dirent->d_name);
 			igt_debug("%sReading file \"%s\"\n", tabs, dirent->d_name);
+			igt_set_timeout(5, "reading sysfs entry");
 
 			sub_fd = openat(path_fd, dirent->d_name, O_RDONLY);
 			if (sub_fd == -1) {
-- 
2.15.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Tvrtko Ursulin]

On 06/12/2017 16:38, Chris Wilson wrote:
> When tracking down the cause of a particular kernel warning, knowing
> which file it is associated with can be a big clue. So write the
> filename into the kernel message log prior to opening it.
> 
> Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> ---
>   tests/debugfs_test.c | 3 ++-
>   1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/tests/debugfs_test.c b/tests/debugfs_test.c
> index 268d6e78f..2e87e4420 100644
> --- a/tests/debugfs_test.c
> +++ b/tests/debugfs_test.c
> @@ -61,8 +61,9 @@ static void read_and_discard_sysfs_entries(int path_fd, int indent)
>   			int sub_fd;
>   			ssize_t ret;
>   
> -			igt_set_timeout(5, "reading sysfs entry");
> +			igt_kmsg(KMSG_DEBUG "Reading file \"%s\"\n", dirent->d_name);
>   			igt_debug("%sReading file \"%s\"\n", tabs, dirent->d_name);
> +			igt_set_timeout(5, "reading sysfs entry");
>   
>   			sub_fd = openat(path_fd, dirent->d_name, O_RDONLY);
>   			if (sub_fd == -1) {
> 

If I may suggest an alternative - timestamp igt messages and write a log 
interleaver to be used with kernel log and igt log as inputs?

That would avoid having to sprinkle igt_kmsg over igt code base as more 
interesting scenarios are discovered.

Regards,

Tvrtko
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Chris Wilson]

Quoting Tvrtko Ursulin (2017-12-06 16:51:24)
> 
> On 06/12/2017 16:38, Chris Wilson wrote:
> > When tracking down the cause of a particular kernel warning, knowing
> > which file it is associated with can be a big clue. So write the
> > filename into the kernel message log prior to opening it.
> > 
> > Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> > ---
> >   tests/debugfs_test.c | 3 ++-
> >   1 file changed, 2 insertions(+), 1 deletion(-)
> > 
> > diff --git a/tests/debugfs_test.c b/tests/debugfs_test.c
> > index 268d6e78f..2e87e4420 100644
> > --- a/tests/debugfs_test.c
> > +++ b/tests/debugfs_test.c
> > @@ -61,8 +61,9 @@ static void read_and_discard_sysfs_entries(int path_fd, int indent)
> >                       int sub_fd;
> >                       ssize_t ret;
> >   
> > -                     igt_set_timeout(5, "reading sysfs entry");
> > +                     igt_kmsg(KMSG_DEBUG "Reading file \"%s\"\n", dirent->d_name);
> >                       igt_debug("%sReading file \"%s\"\n", tabs, dirent->d_name);
> > +                     igt_set_timeout(5, "reading sysfs entry");
> >   
> >                       sub_fd = openat(path_fd, dirent->d_name, O_RDONLY);
> >                       if (sub_fd == -1) {
> > 
> 
> If I may suggest an alternative - timestamp igt messages and write a log 
> interleaver to be used with kernel log and igt log as inputs?

How do you get igt_log over netconsole?
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Tvrtko Ursulin]

On 06/12/2017 17:02, Chris Wilson wrote:
> Quoting Tvrtko Ursulin (2017-12-06 16:51:24)
>>
>> On 06/12/2017 16:38, Chris Wilson wrote:
>>> When tracking down the cause of a particular kernel warning, knowing
>>> which file it is associated with can be a big clue. So write the
>>> filename into the kernel message log prior to opening it.
>>>
>>> Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
>>> ---
>>>    tests/debugfs_test.c | 3 ++-
>>>    1 file changed, 2 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/tests/debugfs_test.c b/tests/debugfs_test.c
>>> index 268d6e78f..2e87e4420 100644
>>> --- a/tests/debugfs_test.c
>>> +++ b/tests/debugfs_test.c
>>> @@ -61,8 +61,9 @@ static void read_and_discard_sysfs_entries(int path_fd, int indent)
>>>                        int sub_fd;
>>>                        ssize_t ret;
>>>    
>>> -                     igt_set_timeout(5, "reading sysfs entry");
>>> +                     igt_kmsg(KMSG_DEBUG "Reading file \"%s\"\n", dirent->d_name);
>>>                        igt_debug("%sReading file \"%s\"\n", tabs, dirent->d_name);
>>> +                     igt_set_timeout(5, "reading sysfs entry");
>>>    
>>>                        sub_fd = openat(path_fd, dirent->d_name, O_RDONLY);
>>>                        if (sub_fd == -1) {
>>>
>>
>> If I may suggest an alternative - timestamp igt messages and write a log
>> interleaver to be used with kernel log and igt log as inputs?
> 
> How do you get igt_log over netconsole?

Hm, ok. But should we then just send igt logs to two places? Stdout/err 
and kmsg? Could be an environment option or something if required.

Regards,

Tvrtko

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Chris Wilson]

Quoting Tvrtko Ursulin (2017-12-06 17:04:40)
> 
> On 06/12/2017 17:02, Chris Wilson wrote:
> > Quoting Tvrtko Ursulin (2017-12-06 16:51:24)
> >>
> >> On 06/12/2017 16:38, Chris Wilson wrote:
> >>> When tracking down the cause of a particular kernel warning, knowing
> >>> which file it is associated with can be a big clue. So write the
> >>> filename into the kernel message log prior to opening it.
> >>>
> >>> Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
> >>> ---
> >>>    tests/debugfs_test.c | 3 ++-
> >>>    1 file changed, 2 insertions(+), 1 deletion(-)
> >>>
> >>> diff --git a/tests/debugfs_test.c b/tests/debugfs_test.c
> >>> index 268d6e78f..2e87e4420 100644
> >>> --- a/tests/debugfs_test.c
> >>> +++ b/tests/debugfs_test.c
> >>> @@ -61,8 +61,9 @@ static void read_and_discard_sysfs_entries(int path_fd, int indent)
> >>>                        int sub_fd;
> >>>                        ssize_t ret;
> >>>    
> >>> -                     igt_set_timeout(5, "reading sysfs entry");
> >>> +                     igt_kmsg(KMSG_DEBUG "Reading file \"%s\"\n", dirent->d_name);
> >>>                        igt_debug("%sReading file \"%s\"\n", tabs, dirent->d_name);
> >>> +                     igt_set_timeout(5, "reading sysfs entry");
> >>>    
> >>>                        sub_fd = openat(path_fd, dirent->d_name, O_RDONLY);
> >>>                        if (sub_fd == -1) {
> >>>
> >>
> >> If I may suggest an alternative - timestamp igt messages and write a log
> >> interleaver to be used with kernel log and igt log as inputs?
> > 
> > How do you get igt_log over netconsole?
> 
> Hm, ok. But should we then just send igt logs to two places? Stdout/err 
> and kmsg? Could be an environment option or something if required.

There are quite a few igt logs that would be nice in the kernel log,
pretty much anything info+. Maybe debug+ if we push some of the noise
out of debug and down into even lower-priority-debug.
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

✓ Fi.CI.BAT: success for series starting with [1/2] lib: Export kmsg()

[Patchwork]

== Series Details ==

Series: series starting with [1/2] lib: Export kmsg()
URL   : https://patchwork.freedesktop.org/series/34974/
State : success

== Summary ==

IGT patchset tested on top of latest successful build
1db12466cb5ad8483cd469753d2e312a62d717b7 meson: build a full dependency for lib_igt_perf

with latest DRM-Tip kernel build CI_DRM_3466
66be57731a40 drm-tip: 2017y-12m-06d-16h-12m-57s UTC integration manifest

No testlist changes.

Test debugfs_test:
        Subgroup read_all_entries:
                dmesg-warn -> PASS       (fi-elk-e7500) fdo#103989 +1
Test gem_mmap_gtt:
        Subgroup basic-small-bo-tiledx:
                pass       -> FAIL       (fi-gdg-551) fdo#102575

fdo#103989 https://bugs.freedesktop.org/show_bug.cgi?id=103989
fdo#102575 https://bugs.freedesktop.org/show_bug.cgi?id=102575

fi-bdw-5557u     total:288  pass:267  dwarn:0   dfail:0   fail:0   skip:21  time:442s
fi-blb-e6850     total:288  pass:223  dwarn:1   dfail:0   fail:0   skip:64  time:390s
fi-bsw-n3050     total:288  pass:242  dwarn:0   dfail:0   fail:0   skip:46  time:528s
fi-bwr-2160      total:288  pass:183  dwarn:0   dfail:0   fail:0   skip:105 time:283s
fi-bxt-dsi       total:288  pass:258  dwarn:0   dfail:0   fail:0   skip:30  time:509s
fi-bxt-j4205     total:288  pass:259  dwarn:0   dfail:0   fail:0   skip:29  time:509s
fi-byt-j1900     total:288  pass:253  dwarn:0   dfail:0   fail:0   skip:35  time:491s
fi-byt-n2820     total:288  pass:249  dwarn:0   dfail:0   fail:0   skip:39  time:476s
fi-elk-e7500     total:224  pass:163  dwarn:15  dfail:0   fail:0   skip:45 
fi-gdg-551       total:288  pass:178  dwarn:1   dfail:0   fail:1   skip:108 time:273s
fi-glk-1         total:288  pass:260  dwarn:0   dfail:0   fail:0   skip:28  time:542s
fi-hsw-4770      total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:375s
fi-hsw-4770r     total:288  pass:224  dwarn:0   dfail:0   fail:0   skip:64  time:267s
fi-ivb-3520m     total:288  pass:259  dwarn:0   dfail:0   fail:0   skip:29  time:484s
fi-ivb-3770      total:288  pass:259  dwarn:0   dfail:0   fail:0   skip:29  time:450s
fi-kbl-7560u     total:288  pass:269  dwarn:0   dfail:0   fail:0   skip:19  time:530s
fi-kbl-7567u     total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:474s
fi-kbl-r         total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:530s
fi-pnv-d510      total:288  pass:222  dwarn:1   dfail:0   fail:0   skip:65  time:589s
fi-skl-6260u     total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:455s
fi-skl-6600u     total:288  pass:261  dwarn:0   dfail:0   fail:0   skip:27  time:542s
fi-skl-6700hq    total:288  pass:262  dwarn:0   dfail:0   fail:0   skip:26  time:569s
fi-skl-6700k     total:288  pass:264  dwarn:0   dfail:0   fail:0   skip:24  time:517s
fi-skl-6770hq    total:288  pass:268  dwarn:0   dfail:0   fail:0   skip:20  time:506s
fi-snb-2520m     total:288  pass:249  dwarn:0   dfail:0   fail:0   skip:39  time:548s
fi-snb-2600      total:288  pass:248  dwarn:0   dfail:0   fail:0   skip:40  time:420s
Blacklisted hosts:
fi-cfl-s2        total:288  pass:262  dwarn:0   dfail:0   fail:0   skip:26  time:603s
fi-cnl-y         total:288  pass:262  dwarn:0   dfail:0   fail:0   skip:26  time:640s
fi-glk-dsi       total:288  pass:258  dwarn:0   dfail:0   fail:0   skip:30  time:498s

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_603/
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

✗ Fi.CI.IGT: warning for series starting with [1/2] lib: Export kmsg()

[Patchwork]

== Series Details ==

Series: series starting with [1/2] lib: Export kmsg()
URL   : https://patchwork.freedesktop.org/series/34974/
State : warning

== Summary ==

Warning: bzip CI_DRM_3466/shard-snb2/results25.json.bz2 wasn't in correct JSON format
Test drv_module_reload:
        Subgroup basic-no-display:
                pass       -> DMESG-WARN (shard-snb) fdo#102707
Test kms_frontbuffer_tracking:
        Subgroup fbc-1p-offscren-pri-shrfb-draw-render:
                pass       -> FAIL       (shard-snb) fdo#101623 +1
Test drv_suspend:
        Subgroup forcewake:
                pass       -> SKIP       (shard-hsw)
Test pm_rps:
        Subgroup waitboost:
                pass       -> FAIL       (shard-hsw) fdo#102250
Test kms_plane:
        Subgroup plane-panning-bottom-right-suspend-pipe-a-planes:
                pass       -> SKIP       (shard-snb) fdo#102365

fdo#102707 https://bugs.freedesktop.org/show_bug.cgi?id=102707
fdo#101623 https://bugs.freedesktop.org/show_bug.cgi?id=101623
fdo#102250 https://bugs.freedesktop.org/show_bug.cgi?id=102250
fdo#102365 https://bugs.freedesktop.org/show_bug.cgi?id=102365

shard-hsw        total:2679 pass:1534 dwarn:1   dfail:0   fail:11  skip:1133 time:9457s
shard-snb        total:2679 pass:1305 dwarn:2   dfail:0   fail:13  skip:1359 time:8053s
Blacklisted hosts:
shard-apl        total:2679 pass:1677 dwarn:2   dfail:0   fail:22  skip:977 time:13579s

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_603/shards.html
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Joonas Lahtinen]

On Wed, 2017-12-06 at 17:02 +0000, Chris Wilson wrote:
> Quoting Tvrtko Ursulin (2017-12-06 16:51:24)
> > 
> > If I may suggest an alternative - timestamp igt messages and write a log 
> > interleaver to be used with kernel log and igt log as inputs?
> 
> How do you get igt_log over netconsole?

With igt-runner? If the idea wasn't rejected :P

Regards, Joonas
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

Re: [PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Chris Wilson]

Quoting Joonas Lahtinen (2017-12-11 11:02:27)
> On Wed, 2017-12-06 at 17:02 +0000, Chris Wilson wrote:
> > Quoting Tvrtko Ursulin (2017-12-06 16:51:24)
> > > 
> > > If I may suggest an alternative - timestamp igt messages and write a log 
> > > interleaver to be used with kernel log and igt log as inputs?
> > 
> > How do you get igt_log over netconsole?
> 
> With igt-runner? If the idea wasn't rejected :P

Speaking of igt-runner,
	tools/testing/selftests/rcutorture/doc/initrd.txt
tl;dr: use dracut

Also on my current agenda is diving into syzkaller.
-Chris
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx

[PATCH igt 2/2] igt/debugfs_tests: Record which file is being opened in kmsg

[Chris Wilson]

When tracking down the cause of a particular kernel warning, knowing
which file it is associated with can be a big clue. So write the
filename into the kernel message log prior to opening it.

Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
---
 tests/debugfs_test.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tests/debugfs_test.c b/tests/debugfs_test.c
index 268d6e78..2e87e442 100644
--- a/tests/debugfs_test.c
+++ b/tests/debugfs_test.c
@@ -61,8 +61,9 @@ static void read_and_discard_sysfs_entries(int path_fd, int indent)
 			int sub_fd;
 			ssize_t ret;
 
-			igt_set_timeout(5, "reading sysfs entry");
+			igt_kmsg(KMSG_DEBUG "Reading file \"%s\"\n", dirent->d_name);
 			igt_debug("%sReading file \"%s\"\n", tabs, dirent->d_name);
+			igt_set_timeout(5, "reading sysfs entry");
 
 			sub_fd = openat(path_fd, dirent->d_name, O_RDONLY);
 			if (sub_fd == -1) {
-- 
2.16.1

_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx