[PATCH] lib/core: Let ftrace know when the test started

[PATCH] lib/core: Let ftrace know when the test started

[Umesh Nerlige Ramappa]

It's useful to know the start and end of the test in ftrace to be able
to debug some issues. Not sure where to add igt_trace for end, so
posting this patch to get some comments.

Signed-off-by: Umesh Nerlige Ramappa <umesh.nerlige.ramappa@intel.com>
---
 lib/igt_core.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/lib/igt_core.c b/lib/igt_core.c
index 407f7b551..6916d6ea4 100644
--- a/lib/igt_core.c
+++ b/lib/igt_core.c
@@ -574,6 +574,9 @@ static void _subtest_starting_message(enum _subtest_type subtest_type,
 	igt_info("Starting %s: %s\n",
 		 subtest_type == _SUBTEST_TYPE_NORMAL ? "subtest" : "dynamic subtest",
 		 name);
+	igt_trace("Starting %s: %s\n",
+		  subtest_type == _SUBTEST_TYPE_NORMAL ? "subtest" : "dynamic subtest",
+		  name);
 	fflush(stdout);
 	if (stderr_needs_sentinel)
 		fprintf(stderr, "Starting %s: %s\n",
-- 
2.38.1

Re: [PATCH] lib/core: Let ftrace know when the test started

[Dixit, Ashutosh]

On Tue, 17 Dec 2024 10:39:10 -0800, Umesh Nerlige Ramappa wrote:
>
> It's useful to know the start and end of the test in ftrace to be able
> to debug some issues. Not sure where to add igt_trace for end, so
> posting this patch to get some comments.

Isn't it this (at least looking at dmesg):

__noreturn static void exit_subtest(const char *result)
{
	...
	igt_kmsg(KMSG_INFO "%s: finished subtest %s, %s\n",
		 command_str, *subtest_name, result);

Re: [PATCH] lib/core: Let ftrace know when the test started

[Kamil Konieczny]

Hi Dixit,,
On 2024-12-17 at 15:19:59 -0800, Dixit, Ashutosh wrote:
> On Tue, 17 Dec 2024 10:39:10 -0800, Umesh Nerlige Ramappa wrote:
> >
> > It's useful to know the start and end of the test in ftrace to be able
> > to debug some issues. Not sure where to add igt_trace for end, so
> > posting this patch to get some comments.
> 
> Isn't it this (at least looking at dmesg):
> 
> __noreturn static void exit_subtest(const char *result)
> {
> 	...
> 	igt_kmsg(KMSG_INFO "%s: finished subtest %s, %s\n",
> 		 command_str, *subtest_name, result);

I also think it is already printed in logs.
Umesh if you find out cases where it is not please drop a link
to CI log(s) to look into.

Now that I look at it again the only diff is a place when it is
printed, this one is after (dynamic) subtest ends but I still
think it is also printed in dmesg before a dynamic subtest starts.

For example look into this log:
https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_12333/shard-snb5/igt@kms_flip@flip-vs-fences@a-vga1.html

there is:
<7> [377.462024] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:75:DP-1] disconnected
<6> [377.463784] [IGT] kms_flip: starting subtest flip-vs-fences
<6> [377.465812] [IGT] kms_flip: starting dynamic subtest A-VGA1

Regards,
Kamil

Re: [PATCH] lib/core: Let ftrace know when the test started

[Dixit, Ashutosh]

On Wed, 18 Dec 2024 11:13:40 -0800, Kamil Konieczny wrote:
>
> Hi Dixit,,
> On 2024-12-17 at 15:19:59 -0800, Dixit, Ashutosh wrote:
> > On Tue, 17 Dec 2024 10:39:10 -0800, Umesh Nerlige Ramappa wrote:
> > >
> > > It's useful to know the start and end of the test in ftrace to be able
> > > to debug some issues. Not sure where to add igt_trace for end, so
> > > posting this patch to get some comments.
> >
> > Isn't it this (at least looking at dmesg):
> >
> > __noreturn static void exit_subtest(const char *result)
> > {
> >	...
> >	igt_kmsg(KMSG_INFO "%s: finished subtest %s, %s\n",
> >		 command_str, *subtest_name, result);
>
> I also think it is already printed in logs.
> Umesh if you find out cases where it is not please drop a link
> to CI log(s) to look into.
>
> Now that I look at it again the only diff is a place when it is
> printed, this one is after (dynamic) subtest ends but I still
> think it is also printed in dmesg before a dynamic subtest starts.
>
> For example look into this log:
> https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_12333/shard-snb5/igt@kms_flip@flip-vs-fences@a-vga1.html
>
> there is:
> <7> [377.462024] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:75:DP-1] disconnected
> <6> [377.463784] [IGT] kms_flip: starting subtest flip-vs-fences
> <6> [377.465812] [IGT] kms_flip: starting dynamic subtest A-VGA1

Umesh wants to print in ftrace not dmesg.

Re: [PATCH] lib/core: Let ftrace know when the test started

[Dixit, Ashutosh]

On Wed, 18 Dec 2024 11:30:14 -0800, Dixit, Ashutosh wrote:
>
> On Wed, 18 Dec 2024 11:13:40 -0800, Kamil Konieczny wrote:
> >
> > Hi Dixit,,
> > On 2024-12-17 at 15:19:59 -0800, Dixit, Ashutosh wrote:
> > > On Tue, 17 Dec 2024 10:39:10 -0800, Umesh Nerlige Ramappa wrote:
> > > >
> > > > It's useful to know the start and end of the test in ftrace to be able
> > > > to debug some issues. Not sure where to add igt_trace for end, so
> > > > posting this patch to get some comments.
> > >
> > > Isn't it this (at least looking at dmesg):
> > >
> > > __noreturn static void exit_subtest(const char *result)
> > > {
> > >	...
> > >	igt_kmsg(KMSG_INFO "%s: finished subtest %s, %s\n",
> > >		 command_str, *subtest_name, result);
> >
> > I also think it is already printed in logs.
> > Umesh if you find out cases where it is not please drop a link
> > to CI log(s) to look into.
> >
> > Now that I look at it again the only diff is a place when it is
> > printed, this one is after (dynamic) subtest ends but I still
> > think it is also printed in dmesg before a dynamic subtest starts.
> >
> > For example look into this log:
> > https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_12333/shard-snb5/igt@kms_flip@flip-vs-fences@a-vga1.html
> >
> > there is:
> > <7> [377.462024] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:75:DP-1] disconnected
> > <6> [377.463784] [IGT] kms_flip: starting subtest flip-vs-fences
> > <6> [377.465812] [IGT] kms_flip: starting dynamic subtest A-VGA1
>
> Umesh wants to print in ftrace not dmesg.

Sorry, better to say ftrace as well as dmesg.

Re: [PATCH] lib/core: Let ftrace know when the test started

[Kamil Konieczny]

Hi Dixit,,
On 2024-12-18 at 11:31:00 -0800, Dixit, Ashutosh wrote:
> On Wed, 18 Dec 2024 11:30:14 -0800, Dixit, Ashutosh wrote:
> >
> > On Wed, 18 Dec 2024 11:13:40 -0800, Kamil Konieczny wrote:
> > >
> > > Hi Dixit,,
> > > On 2024-12-17 at 15:19:59 -0800, Dixit, Ashutosh wrote:
> > > > On Tue, 17 Dec 2024 10:39:10 -0800, Umesh Nerlige Ramappa wrote:
> > > > >
> > > > > It's useful to know the start and end of the test in ftrace to be able
> > > > > to debug some issues. Not sure where to add igt_trace for end, so
> > > > > posting this patch to get some comments.
> > > >
> > > > Isn't it this (at least looking at dmesg):
> > > >
> > > > __noreturn static void exit_subtest(const char *result)
> > > > {
> > > >	...
> > > >	igt_kmsg(KMSG_INFO "%s: finished subtest %s, %s\n",
> > > >		 command_str, *subtest_name, result);
> > >
> > > I also think it is already printed in logs.
> > > Umesh if you find out cases where it is not please drop a link
> > > to CI log(s) to look into.
> > >
> > > Now that I look at it again the only diff is a place when it is
> > > printed, this one is after (dynamic) subtest ends but I still
> > > think it is also printed in dmesg before a dynamic subtest starts.
> > >
> > > For example look into this log:
> > > https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_12333/shard-snb5/igt@kms_flip@flip-vs-fences@a-vga1.html
> > >
> > > there is:
> > > <7> [377.462024] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:75:DP-1] disconnected
> > > <6> [377.463784] [IGT] kms_flip: starting subtest flip-vs-fences
> > > <6> [377.465812] [IGT] kms_flip: starting dynamic subtest A-VGA1
> >
> > Umesh wants to print in ftrace not dmesg.
> 
> Sorry, better to say ftrace as well as dmesg.

Ah, sorry, I misunderstood it, it is ok for me so

Reviewed-by: Kamil Konieczny <kamil.konieczny@linux.intel.com>

Btw one more question before merge, is it safe to call it
even without actual trace enabled? Could it slow down testing?

Or maybe we should add an option to igt for it?

+cc Petri and Lucas.

Also please restart testing for it in our CI if you plan on
merging this change.

Regards,
Kamil

Re: [PATCH] lib/core: Let ftrace know when the test started

[Umesh Nerlige Ramappa]

On Fri, Dec 20, 2024 at 07:31:17PM +0100, Kamil Konieczny wrote:
>Hi Dixit,,
>On 2024-12-18 at 11:31:00 -0800, Dixit, Ashutosh wrote:
>> On Wed, 18 Dec 2024 11:30:14 -0800, Dixit, Ashutosh wrote:
>> >
>> > On Wed, 18 Dec 2024 11:13:40 -0800, Kamil Konieczny wrote:
>> > >
>> > > Hi Dixit,,
>> > > On 2024-12-17 at 15:19:59 -0800, Dixit, Ashutosh wrote:
>> > > > On Tue, 17 Dec 2024 10:39:10 -0800, Umesh Nerlige Ramappa wrote:
>> > > > >
>> > > > > It's useful to know the start and end of the test in ftrace to be able
>> > > > > to debug some issues. Not sure where to add igt_trace for end, so
>> > > > > posting this patch to get some comments.
>> > > >
>> > > > Isn't it this (at least looking at dmesg):
>> > > >
>> > > > __noreturn static void exit_subtest(const char *result)
>> > > > {
>> > > >	...
>> > > >	igt_kmsg(KMSG_INFO "%s: finished subtest %s, %s\n",
>> > > >		 command_str, *subtest_name, result);
>> > >
>> > > I also think it is already printed in logs.
>> > > Umesh if you find out cases where it is not please drop a link
>> > > to CI log(s) to look into.
>> > >
>> > > Now that I look at it again the only diff is a place when it is
>> > > printed, this one is after (dynamic) subtest ends but I still
>> > > think it is also printed in dmesg before a dynamic subtest starts.
>> > >
>> > > For example look into this log:
>> > > https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_12333/shard-snb5/igt@kms_flip@flip-vs-fences@a-vga1.html
>> > >
>> > > there is:
>> > > <7> [377.462024] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:75:DP-1] disconnected
>> > > <6> [377.463784] [IGT] kms_flip: starting subtest flip-vs-fences
>> > > <6> [377.465812] [IGT] kms_flip: starting dynamic subtest A-VGA1
>> >
>> > Umesh wants to print in ftrace not dmesg.
>>
>> Sorry, better to say ftrace as well as dmesg.
>
>Ah, sorry, I misunderstood it, it is ok for me so
>
>Reviewed-by: Kamil Konieczny <kamil.konieczny@linux.intel.com>
>
>Btw one more question before merge, is it safe to call it
>even without actual trace enabled? Could it slow down testing?

generic ftrace is enabled by default in linux, but may not be turned on.  
If it is not turned on, then the log is just discarded, so it should not 
affect IGT.

Note that my intent is to have the user turn on ftrace when needed and 
not to turn it on in IGT library.

When the user does turn it on, we would also see the IGT start and end 
messages for a test in ftrace.

>
>Or maybe we should add an option to igt for it?
>
>+cc Petri and Lucas.
>
>Also please restart testing for it in our CI if you plan on
>merging this change.

I need to post another revision with the log added to the test end like 
Ashutosh is suggesting. I will try that out and repost.

Thanks,
Umesh
>
>Regards,
>Kamil
>