odd TRACE_DEFINE_ENUM behavior

odd TRACE_DEFINE_ENUM behavior

[Chuck Lever]

Hi Steven-

In commit 8224b2734ab1 ("NFS: Add static NFS I/O tracepoints") I added
nfs_show_stable to symbolically display the value of the NFS WRITE stable
field. However, I couldn't get the thing to work with the already-defined
enums in linux/nfs.h, and had to resort to coding numeric constants:

799 /*
800  * XXX: I tried using NFS_UNSTABLE and friends in this table, but they
801  * all evaluate to 0 for some reason, even if I include linux/nfs.h.
802  */
803 #define nfs_show_stable(stable) \
804         __print_symbolic(stable, \
805                         { 0, " (UNSTABLE)" }, \
806                         { 1, " (DATA_SYNC)" }, \
807                         { 2, " (FILE_SYNC)" })

If I code this macro the way the others are written, ie:

TRACE_DEFINE_ENUM(NFS_UNSTABLE);
TRACE_DEFINE_ENUM(NFS_DATA_SYNC);
TRACE_DEFINE_ENUM(NFS_FILE_SYNC);

#define nfs_show_stable(stable) \
	__print_symbolic(stable, \
			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
			{ NFS_FILE_SYNC, " (FILE_SYNC)" })

When the field contains 0 it displays "(UNSTABLE)", and when the field
contains a non-zero value the displayed symbol is blank.

More recently I observed a similar issue when adding static trace points
in net/sunrpc/xprtrdma/ , and with existing __print_symbolic call sites
in sunrpc.ko.

There is no file /sys/kernel/debug/tracing/enum_map on my system.

Am I missing something?


--
Chuck Lever

Re: odd TRACE_DEFINE_ENUM behavior

[Steven Rostedt]

On Thu, 4 Jan 2018 11:13:03 -0500
Chuck Lever <chuck.lever@oracle.com> wrote:

> Hi Steven-
> 
> In commit 8224b2734ab1 ("NFS: Add static NFS I/O tracepoints") I added
> nfs_show_stable to symbolically display the value of the NFS WRITE stable
> field. However, I couldn't get the thing to work with the already-defined
> enums in linux/nfs.h, and had to resort to coding numeric constants:
> 
> 799 /*
> 800  * XXX: I tried using NFS_UNSTABLE and friends in this table, but they
> 801  * all evaluate to 0 for some reason, even if I include linux/nfs.h.
> 802  */
> 803 #define nfs_show_stable(stable) \
> 804         __print_symbolic(stable, \
> 805                         { 0, " (UNSTABLE)" }, \
> 806                         { 1, " (DATA_SYNC)" }, \
> 807                         { 2, " (FILE_SYNC)" })
> 
> If I code this macro the way the others are written, ie:
> 
> TRACE_DEFINE_ENUM(NFS_UNSTABLE);
> TRACE_DEFINE_ENUM(NFS_DATA_SYNC);
> TRACE_DEFINE_ENUM(NFS_FILE_SYNC);
> 
> #define nfs_show_stable(stable) \
> 	__print_symbolic(stable, \
> 			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
> 			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
> 			{ NFS_FILE_SYNC, " (FILE_SYNC)" })
> 
> When the field contains 0 it displays "(UNSTABLE)", and when the field
> contains a non-zero value the displayed symbol is blank.
nfs_initiate_write,
Can you show my what is in

 /sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format

> 
> More recently I observed a similar issue when adding static trace points
> in net/sunrpc/xprtrdma/ , and with existing __print_symbolic call sites
> in sunrpc.ko.
> 
> There is no file /sys/kernel/debug/tracing/enum_map on my system.

That's a debug feature. You need to enable CONFIG_TRACE_ENUM_MAP_FILE

-- Steve

> 
> Am I missing something?
> 
> 
> --
> Chuck Lever
> 
> 

Re: odd TRACE_DEFINE_ENUM behavior

[Chuck Lever]

> On Jan 4, 2018, at 1:08 PM, Steven Rostedt <rostedt@goodmis.org> =
wrote:
>=20
> On Thu, 4 Jan 2018 11:13:03 -0500
> Chuck Lever <chuck.lever@oracle.com> wrote:
>=20
>> Hi Steven-
>>=20
>> In commit 8224b2734ab1 ("NFS: Add static NFS I/O tracepoints") I =
added
>> nfs_show_stable to symbolically display the value of the NFS WRITE =
stable
>> field. However, I couldn't get the thing to work with the =
already-defined
>> enums in linux/nfs.h, and had to resort to coding numeric constants:
>>=20
>> 799 /*
>> 800  * XXX: I tried using NFS_UNSTABLE and friends in this table, but =
they
>> 801  * all evaluate to 0 for some reason, even if I include =
linux/nfs.h.
>> 802  */
>> 803 #define nfs_show_stable(stable) \
>> 804         __print_symbolic(stable, \
>> 805                         { 0, " (UNSTABLE)" }, \
>> 806                         { 1, " (DATA_SYNC)" }, \
>> 807                         { 2, " (FILE_SYNC)" })
>>=20
>> If I code this macro the way the others are written, ie:
>>=20
>> TRACE_DEFINE_ENUM(NFS_UNSTABLE);
>> TRACE_DEFINE_ENUM(NFS_DATA_SYNC);
>> TRACE_DEFINE_ENUM(NFS_FILE_SYNC);
>>=20
>> #define nfs_show_stable(stable) \
>> 	__print_symbolic(stable, \
>> 			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
>> 			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
>> 			{ NFS_FILE_SYNC, " (FILE_SYNC)" })
>>=20
>> When the field contains 0 it displays "(UNSTABLE)", and when the =
field
>> contains a non-zero value the displayed symbol is blank.
> nfs_initiate_write,
> Can you show my what is in
>=20
> /sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format

This is with current v4.15-rc6 code base:

name: nfs_initiate_write
ID: 1818
format:
	field:unsigned short common_type;	offset:0;	size:2;	=
signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	=
signed:0;
	field:unsigned char common_preempt_count;	offset:3;	=
size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:loff_t offset;	offset:8;	size:8;	signed:1;
	field:unsigned long count;	offset:16;	size:8;	=
signed:0;
	field:enum nfs3_stable_how stable;	offset:24;	size:4;	=
signed:1;
	field:dev_t dev;	offset:28;	size:4;	signed:0;
	field:u32 fhandle;	offset:32;	size:4;	signed:0;
	field:u64 fileid;	offset:40;	size:8;	signed:0;

print fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d%s", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, " (UNSTABLE)" }, { 1, " (DATA_SYNC)" =
}, { 2, " (FILE_SYNC)" })


>> More recently I observed a similar issue when adding static trace =
points
>> in net/sunrpc/xprtrdma/ , and with existing __print_symbolic call =
sites
>> in sunrpc.ko.
>>=20
>> There is no file /sys/kernel/debug/tracing/enum_map on my system.
>=20
> That's a debug feature. You need to enable CONFIG_TRACE_ENUM_MAP_FILE
>=20
> -- Steve
>=20
>>=20
>> Am I missing something?
>>=20
>>=20
>> --
>> Chuck Lever

--
Chuck Lever

Re: odd TRACE_DEFINE_ENUM behavior

[Steven Rostedt]

On Thu, 4 Jan 2018 14:10:21 -0500
Chuck Lever <chuck.lever@oracle.com> wrote:

> >> #define nfs_show_stable(stable) \
> >> 	__print_symbolic(stable, \
> >> 			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
> >> 			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
> >> 			{ NFS_FILE_SYNC, " (FILE_SYNC)" })
> >> 
> >> When the field contains 0 it displays "(UNSTABLE)", and when the field
> >> contains a non-zero value the displayed symbol is blank.  
> > nfs_initiate_write,
> > Can you show my what is in

Are you sure that it isn't another number there?

> > 
> > /sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format  
> 
> This is with current v4.15-rc6 code base:
> 
> name: nfs_initiate_write
> ID: 1818
> format:
> 	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
> 	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
> 	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
> 	field:int common_pid;	offset:4;	size:4;	signed:1;
> 
> 	field:loff_t offset;	offset:8;	size:8;	signed:1;
> 	field:unsigned long count;	offset:16;	size:8;	signed:0;
> 	field:enum nfs3_stable_how stable;	offset:24;	size:4;	signed:1;
> 	field:dev_t dev;	offset:28;	size:4;	signed:0;
> 	field:u32 fhandle;	offset:32;	size:4;	signed:0;
> 	field:u64 fileid;	offset:40;	size:8;	signed:0;
> 
> print fmt: "fileid=%02x:%02x:%llu fhandle=0x%08x offset=%lld count=%lu stable=%d%s", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, __print_symbolic(REC->stable, { 0, " (UNSTABLE)" }, { 1, " (DATA_SYNC)" }, { 2, " (FILE_SYNC)" })

This looks like it should work fine.

Can you try this:

	trace-cmd record -e nfs_initiate_write

do stuff to trigger the event, then hit Ctrl^C

See if "trace-cmd report" shows it. If not do:

	trace-cmd report -R

Which will suppress the translation of the output and show you the raw
values. That way, you will see what is in the stable field.

-- Steve

Re: odd TRACE_DEFINE_ENUM behavior

[Chuck Lever]

> On Jan 4, 2018, at 2:36 PM, Steven Rostedt <rostedt@goodmis.org> =
wrote:
>=20
> On Thu, 4 Jan 2018 14:10:21 -0500
> Chuck Lever <chuck.lever@oracle.com> wrote:
>=20
>>>> #define nfs_show_stable(stable) \
>>>> 	__print_symbolic(stable, \
>>>> 			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
>>>> 			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
>>>> 			{ NFS_FILE_SYNC, " (FILE_SYNC)" })
>>>>=20
>>>> When the field contains 0 it displays "(UNSTABLE)", and when the =
field
>>>> contains a non-zero value the displayed symbol is blank. =20
>>> nfs_initiate_write,
>>> Can you show my what is in
>=20
> Are you sure that it isn't another number there?

Yes.


>>> /sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format =20
>>=20
>> This is with current v4.15-rc6 code base:
>>=20
>> name: nfs_initiate_write
>> ID: 1818
>> format:
>> 	field:unsigned short common_type;	offset:0;	size:2;	=
signed:0;
>> 	field:unsigned char common_flags;	offset:2;	size:1;	=
signed:0;
>> 	field:unsigned char common_preempt_count;	offset:3;	=
size:1;	signed:0;
>> 	field:int common_pid;	offset:4;	size:4;	signed:1;
>>=20
>> 	field:loff_t offset;	offset:8;	size:8;	signed:1;
>> 	field:unsigned long count;	offset:16;	size:8;	=
signed:0;
>> 	field:enum nfs3_stable_how stable;	offset:24;	size:4;	=
signed:1;
>> 	field:dev_t dev;	offset:28;	size:4;	signed:0;
>> 	field:u32 fhandle;	offset:32;	size:4;	signed:0;
>> 	field:u64 fileid;	offset:40;	size:8;	signed:0;
>>=20
>> print fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d%s", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, " (UNSTABLE)" }, { 1, " (DATA_SYNC)" =
}, { 2, " (FILE_SYNC)" })
>=20
> This looks like it should work fine.

This does work fine. The source code avoids using TRACE_DEFINE_ENUM.
Do you want me to wire up the "proper" way to implement nfs_show_stable
and we can experiment on that?


> Can you try this:
>=20
> 	trace-cmd record -e nfs_initiate_write
>=20
> do stuff to trigger the event, then hit Ctrl^C
>=20
> See if "trace-cmd report" shows it. If not do:
>=20
> 	trace-cmd report -R
>=20
> Which will suppress the translation of the output and show you the raw
> values. That way, you will see what is in the stable field.


--
Chuck Lever

Re: odd TRACE_DEFINE_ENUM behavior

[Chuck Lever]

> On Jan 4, 2018, at 2:39 PM, Chuck Lever <chuck.lever@oracle.com> =
wrote:
>=20
>>=20
>> On Jan 4, 2018, at 2:36 PM, Steven Rostedt <rostedt@goodmis.org> =
wrote:
>>=20
>> On Thu, 4 Jan 2018 14:10:21 -0500
>> Chuck Lever <chuck.lever@oracle.com> wrote:
>>=20
>>>>> #define nfs_show_stable(stable) \
>>>>> 	__print_symbolic(stable, \
>>>>> 			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
>>>>> 			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
>>>>> 			{ NFS_FILE_SYNC, " (FILE_SYNC)" })
>>>>>=20
>>>>> When the field contains 0 it displays "(UNSTABLE)", and when the =
field
>>>>> contains a non-zero value the displayed symbol is blank. =20
>>>> nfs_initiate_write,
>>>> Can you show my what is in
>>=20
>> Are you sure that it isn't another number there?
>=20
> Yes.
>=20
>=20
>>>> /sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format =20
>>>=20
>>> This is with current v4.15-rc6 code base:
>>>=20
>>> name: nfs_initiate_write
>>> ID: 1818
>>> format:
>>> 	field:unsigned short common_type;	offset:0;	size:2;	=
signed:0;
>>> 	field:unsigned char common_flags;	offset:2;	size:1;	=
signed:0;
>>> 	field:unsigned char common_preempt_count;	offset:3;	=
size:1;	signed:0;
>>> 	field:int common_pid;	offset:4;	size:4;	signed:1;
>>>=20
>>> 	field:loff_t offset;	offset:8;	size:8;	signed:1;
>>> 	field:unsigned long count;	offset:16;	size:8;	=
signed:0;
>>> 	field:enum nfs3_stable_how stable;	offset:24;	size:4;	=
signed:1;
>>> 	field:dev_t dev;	offset:28;	size:4;	signed:0;
>>> 	field:u32 fhandle;	offset:32;	size:4;	signed:0;
>>> 	field:u64 fileid;	offset:40;	size:8;	signed:0;
>>>=20
>>> print fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d%s", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, " (UNSTABLE)" }, { 1, " (DATA_SYNC)" =
}, { 2, " (FILE_SYNC)" })
>>=20
>> This looks like it should work fine.
>=20
> This does work fine. The source code avoids using TRACE_DEFINE_ENUM.
> Do you want me to wire up the "proper" way to implement =
nfs_show_stable
> and we can experiment on that?

include/linux/nfs.h has:

 47 enum nfs3_stable_how {
 48         NFS_UNSTABLE =3D 0,
 49         NFS_DATA_SYNC =3D 1,
 50         NFS_FILE_SYNC =3D 2,
 51=20
 52         /* used by direct.c to mark verf as invalid */
 53         NFS_INVALID_STABLE_HOW =3D -1
 54 };

I applied this patch to v4.15-rc6:

diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 093290c..94d4f2e 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -796,15 +796,15 @@
                )
 );
=20
-/*
- * XXX: I tried using NFS_UNSTABLE and friends in this table, but they
- * all evaluate to 0 for some reason, even if I include linux/nfs.h.
- */
+TRACE_DEFINE_ENUM(NFS_UNSTABLE);
+TRACE_DEFINE_ENUM(NFS_DATA_SYNC);
+TRACE_DEFINE_ENUM(NFS_FILE_SYNC);
+
 #define nfs_show_stable(stable) \
        __print_symbolic(stable, \
-                       { 0, " (UNSTABLE)" }, \
-                       { 1, " (DATA_SYNC)" }, \
-                       { 2, " (FILE_SYNC)" })
+                       { NFS_UNSTABLE, " (UNSTABLE)" }, \
+                       { NFS_DATA_SYNC, " (DATA_SYNC)" }, \
+                       { NFS_FILE_SYNC, " (FILE_SYNC)" })
=20
 TRACE_EVENT(nfs_initiate_write,
                TP_PROTO(


eval_map now has this:

NFS_FILE_SYNC 2 (nfs)
NFS_DATA_SYNC 1 (nfs)
NFS_UNSTABLE 0 (nfs)

but nfs_initiate_write/format has this:

name: nfs_initiate_write
ID: 1818
format:
	field:unsigned short common_type;	offset:0;	size:2;	=
signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	=
signed:0;
	field:unsigned char common_preempt_count;	offset:3;	=
size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:loff_t offset;	offset:8;	size:8;	signed:1;
	field:unsigned long count;	offset:16;	size:8;	=
signed:0;
	field:enum nfs3_stable_how stable;	offset:24;	size:4;	=
signed:1;
	field:dev_t dev;	offset:28;	size:4;	signed:0;
	field:u32 fhandle;	offset:32;	size:4;	signed:0;
	field:u64 fileid;	offset:40;	size:8;	signed:0;

print fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d%s", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, " (UNSTABLE)" }, { 1, " (DATA_SYNC)" =
}, { NFS_FILE_SYNC, " (FILE_SYNC)" })

Which is a little screwy.


>> Can you try this:
>>=20
>> 	trace-cmd record -e nfs_initiate_write
>>=20
>> do stuff to trigger the event, then hit Ctrl^C
>>=20
>> See if "trace-cmd report" shows it. If not do:
>>=20
>> 	trace-cmd report -R
>>=20
>> Which will suppress the translation of the output and show you the =
raw
>> values. That way, you will see what is in the stable field.
>=20
>=20
> --
> Chuck Lever
>=20
>=20
>=20
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" =
in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

--
Chuck Lever

Re: odd TRACE_DEFINE_ENUM behavior

[Chuck Lever]

> On Jan 4, 2018, at 2:36 PM, Steven Rostedt <rostedt@goodmis.org> =
wrote:
>=20
> On Thu, 4 Jan 2018 14:10:21 -0500
> Chuck Lever <chuck.lever@oracle.com> wrote:
>=20
>>>> #define nfs_show_stable(stable) \
>>>> 	__print_symbolic(stable, \
>>>> 			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
>>>> 			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
>>>> 			{ NFS_FILE_SYNC, " (FILE_SYNC)" })
>>>>=20
>>>> When the field contains 0 it displays "(UNSTABLE)", and when the =
field
>>>> contains a non-zero value the displayed symbol is blank. =20
>>> nfs_initiate_write,
>>> Can you show my what is in
>=20
> Are you sure that it isn't another number there?
>=20
>>>=20
>>> /sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format =20
>>=20
>> This is with current v4.15-rc6 code base:
>>=20
>> name: nfs_initiate_write
>> ID: 1818
>> format:
>> 	field:unsigned short common_type;	offset:0;	size:2;	=
signed:0;
>> 	field:unsigned char common_flags;	offset:2;	size:1;	=
signed:0;
>> 	field:unsigned char common_preempt_count;	offset:3;	=
size:1;	signed:0;
>> 	field:int common_pid;	offset:4;	size:4;	signed:1;
>>=20
>> 	field:loff_t offset;	offset:8;	size:8;	signed:1;
>> 	field:unsigned long count;	offset:16;	size:8;	=
signed:0;
>> 	field:enum nfs3_stable_how stable;	offset:24;	size:4;	=
signed:1;
>> 	field:dev_t dev;	offset:28;	size:4;	signed:0;
>> 	field:u32 fhandle;	offset:32;	size:4;	signed:0;
>> 	field:u64 fileid;	offset:40;	size:8;	signed:0;
>>=20
>> print fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d%s", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, " (UNSTABLE)" }, { 1, " (DATA_SYNC)" =
}, { 2, " (FILE_SYNC)" })
>=20
> This looks like it should work fine.
>=20
> Can you try this:
>=20
> 	trace-cmd record -e nfs_initiate_write
>=20
> do stuff to trigger the event, then hit Ctrl^C
>=20
> See if "trace-cmd report" shows it. If not do:
>=20
> 	trace-cmd report -R
>=20
> Which will suppress the translation of the output and show you the raw
> values. That way, you will see what is in the stable field.

This is with:

TRACE_DEFINE_ENUM(NFS_UNSTABLE);
TRACE_DEFINE_ENUM(NFS_DATA_SYNC);
TRACE_DEFINE_ENUM(NFS_FILE_SYNC);

#define nfs_show_stable(stable) \
       __print_symbolic(stable, \
                        { NFS_UNSTABLE, "NFS_UNSTABLE" }, \
                        { NFS_DATA_SYNC, "NFS_DATA_SYNC" }, \
                        { NFS_FILE_SYNC, "NFS_FILE_SYNC" })

Here's "cat =
/sys/kernel/debug/events/tracing/nfs/nfs_initiate_write/format" :

print_fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d (%s)", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, "NFS_UNSTABLE" }, { 1, =
"NFS_DATA_SYNC" }, { NFS_FILE_SYNC, "NFS_FILE_SYNC" })

The last element in the __print_symbolic table is wrong. For comparison,
here's an excerpt of "strings nfs.ko | grep NFS_FILE_SYNC" :

"fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld count=3D%lu =
stable=3D%d (%s)", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) =
((REC->dev) & ((1U << 20) - 1))), (unsigned long long)REC->fileid, =
REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { NFS_UNSTABLE, "NFS_UNSTABLE" }, { =
NFS_DATA_SYNC, "NFS_DATA_SYNC" }, { NFS_FILE_SYNC, "NFS_FILE_SYNC" })

Note this copy of the table contains three symbolic names. I haven't =
been
able to find the code that adjusts the print_fmt string to understand =
the
difference with the output from "cat /sys/kernel ..." . But that code
doesn't seem to adjust the last element in the __print_symbolic table.


trace-cmd report

           <...>-11353 [001]  6211.728494: nfs_initiate_write:   =
fileid=3D00:2a:301409 fhandle=3D0x820b4b2e offset=3D0 count=3D601 =
stable=3D2 ()
           <...>-11353 [004]  6211.728783: nfs_initiate_write:   =
fileid=3D00:2a:301410 fhandle=3D0x0c844ccd offset=3D0 count=3D738 =
stable=3D2 ()
           <...>-11353 [001]  6211.729023: nfs_initiate_write:   =
fileid=3D00:2a:301411 fhandle=3D0xc02e4c53 offset=3D0 count=3D4015 =
stable=3D2 ()
           <...>-11353 [005]  6211.729351: nfs_initiate_write:   =
fileid=3D00:2a:301412 fhandle=3D0xcaeb454a offset=3D0 count=3D282 =
stable=3D2 ()
           <...>-11353 [003]  6211.729651: nfs_initiate_write:   =
fileid=3D00:2a:301413 fhandle=3D0x064145d4 offset=3D0 count=3D7688 =
stable=3D2 ()

trace-cmd report -R

           <...>-11353 [001]  6211.728494: nfs_initiate_write:    =
offset=3D0 count=3D0x259 stable=3D2 dev=3D42 fhandle=3D2181778222 =
fileid=3D301409
           <...>-11353 [004]  6211.728783: nfs_initiate_write:    =
offset=3D0 count=3D0x2e2 stable=3D2 dev=3D42 fhandle=3D209997005 =
fileid=3D301410
           <...>-11353 [001]  6211.729023: nfs_initiate_write:    =
offset=3D0 count=3D0xfaf stable=3D2 dev=3D42 fhandle=3D3224259667 =
fileid=3D301411
           <...>-11353 [005]  6211.729351: nfs_initiate_write:    =
offset=3D0 count=3D0x11a stable=3D2 dev=3D42 fhandle=3D3404416330 =
fileid=3D301412
           <...>-11353 [003]  6211.729651: nfs_initiate_write:    =
offset=3D0 count=3D0x1e08 stable=3D2 dev=3D42 fhandle=3D104941012 =
fileid=3D301413

Thanks for your advice!


--
Chuck Lever

Re: odd TRACE_DEFINE_ENUM behavior

[Chuck Lever]

> On Jan 9, 2018, at 5:35 PM, Chuck Lever <chuck.lever@oracle.com> =
wrote:
>=20
>=20
>=20
>> On Jan 4, 2018, at 2:36 PM, Steven Rostedt <rostedt@goodmis.org> =
wrote:
>>=20
>> On Thu, 4 Jan 2018 14:10:21 -0500
>> Chuck Lever <chuck.lever@oracle.com> wrote:
>>=20
>>>>> #define nfs_show_stable(stable) \
>>>>> 	__print_symbolic(stable, \
>>>>> 			{ NFS_UNSTABLE, " (UNSTABLE)" }, \
>>>>> 			{ NFS_DATA_SYNC, " (DATA_SYNC)" }, \
>>>>> 			{ NFS_FILE_SYNC, " (FILE_SYNC)" })
>>>>>=20
>>>>> When the field contains 0 it displays "(UNSTABLE)", and when the =
field
>>>>> contains a non-zero value the displayed symbol is blank. =20
>>>> nfs_initiate_write,
>>>> Can you show my what is in
>>=20
>> Are you sure that it isn't another number there?
>>=20
>>>>=20
>>>> /sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format =20
>>>=20
>>> This is with current v4.15-rc6 code base:
>>>=20
>>> name: nfs_initiate_write
>>> ID: 1818
>>> format:
>>> 	field:unsigned short common_type;	offset:0;	size:2;	=
signed:0;
>>> 	field:unsigned char common_flags;	offset:2;	size:1;	=
signed:0;
>>> 	field:unsigned char common_preempt_count;	offset:3;	=
size:1;	signed:0;
>>> 	field:int common_pid;	offset:4;	size:4;	signed:1;
>>>=20
>>> 	field:loff_t offset;	offset:8;	size:8;	signed:1;
>>> 	field:unsigned long count;	offset:16;	size:8;	=
signed:0;
>>> 	field:enum nfs3_stable_how stable;	offset:24;	size:4;	=
signed:1;
>>> 	field:dev_t dev;	offset:28;	size:4;	signed:0;
>>> 	field:u32 fhandle;	offset:32;	size:4;	signed:0;
>>> 	field:u64 fileid;	offset:40;	size:8;	signed:0;
>>>=20
>>> print fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d%s", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, " (UNSTABLE)" }, { 1, " (DATA_SYNC)" =
}, { 2, " (FILE_SYNC)" })
>>=20
>> This looks like it should work fine.
>>=20
>> Can you try this:
>>=20
>> 	trace-cmd record -e nfs_initiate_write
>>=20
>> do stuff to trigger the event, then hit Ctrl^C
>>=20
>> See if "trace-cmd report" shows it. If not do:
>>=20
>> 	trace-cmd report -R
>>=20
>> Which will suppress the translation of the output and show you the =
raw
>> values. That way, you will see what is in the stable field.
>=20
> This is with:
>=20
> TRACE_DEFINE_ENUM(NFS_UNSTABLE);
> TRACE_DEFINE_ENUM(NFS_DATA_SYNC);
> TRACE_DEFINE_ENUM(NFS_FILE_SYNC);
>=20
> #define nfs_show_stable(stable) \
>       __print_symbolic(stable, \
>                        { NFS_UNSTABLE, "NFS_UNSTABLE" }, \
>                        { NFS_DATA_SYNC, "NFS_DATA_SYNC" }, \
>                        { NFS_FILE_SYNC, "NFS_FILE_SYNC" })
>=20
> Here's "cat =
/sys/kernel/debug/events/tracing/nfs/nfs_initiate_write/format" :
>=20
> print_fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%d (%s)", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, "NFS_UNSTABLE" }, { 1, =
"NFS_DATA_SYNC" }, { NFS_FILE_SYNC, "NFS_FILE_SYNC" })
>=20
> The last element in the __print_symbolic table is wrong. For =
comparison,
> here's an excerpt of "strings nfs.ko | grep NFS_FILE_SYNC" :
>=20
> "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld count=3D%lu =
stable=3D%d (%s)", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) =
((REC->dev) & ((1U << 20) - 1))), (unsigned long long)REC->fileid, =
REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { NFS_UNSTABLE, "NFS_UNSTABLE" }, { =
NFS_DATA_SYNC, "NFS_DATA_SYNC" }, { NFS_FILE_SYNC, "NFS_FILE_SYNC" })
>=20
> Note this copy of the table contains three symbolic names. I haven't =
been
> able to find the code that adjusts the print_fmt string to understand =
the
> difference with the output from "cat /sys/kernel ..." . But that code
> doesn't seem to adjust the last element in the __print_symbolic table.
>=20
>=20
> trace-cmd report
>=20
>           <...>-11353 [001]  6211.728494: nfs_initiate_write:   =
fileid=3D00:2a:301409 fhandle=3D0x820b4b2e offset=3D0 count=3D601 =
stable=3D2 ()
>           <...>-11353 [004]  6211.728783: nfs_initiate_write:   =
fileid=3D00:2a:301410 fhandle=3D0x0c844ccd offset=3D0 count=3D738 =
stable=3D2 ()
>           <...>-11353 [001]  6211.729023: nfs_initiate_write:   =
fileid=3D00:2a:301411 fhandle=3D0xc02e4c53 offset=3D0 count=3D4015 =
stable=3D2 ()
>           <...>-11353 [005]  6211.729351: nfs_initiate_write:   =
fileid=3D00:2a:301412 fhandle=3D0xcaeb454a offset=3D0 count=3D282 =
stable=3D2 ()
>           <...>-11353 [003]  6211.729651: nfs_initiate_write:   =
fileid=3D00:2a:301413 fhandle=3D0x064145d4 offset=3D0 count=3D7688 =
stable=3D2 ()
>=20
> trace-cmd report -R
>=20
>           <...>-11353 [001]  6211.728494: nfs_initiate_write:    =
offset=3D0 count=3D0x259 stable=3D2 dev=3D42 fhandle=3D2181778222 =
fileid=3D301409
>           <...>-11353 [004]  6211.728783: nfs_initiate_write:    =
offset=3D0 count=3D0x2e2 stable=3D2 dev=3D42 fhandle=3D209997005 =
fileid=3D301410
>           <...>-11353 [001]  6211.729023: nfs_initiate_write:    =
offset=3D0 count=3D0xfaf stable=3D2 dev=3D42 fhandle=3D3224259667 =
fileid=3D301411
>           <...>-11353 [005]  6211.729351: nfs_initiate_write:    =
offset=3D0 count=3D0x11a stable=3D2 dev=3D42 fhandle=3D3404416330 =
fileid=3D301412
>           <...>-11353 [003]  6211.729651: nfs_initiate_write:    =
offset=3D0 count=3D0x1e08 stable=3D2 dev=3D42 fhandle=3D104941012 =
fileid=3D301413
>=20
> Thanks for your advice!

The problem is in this function (kernel/trace/trace_events.c):

2212 void trace_event_eval_update(struct trace_eval_map **map, int len)
2213 {
2214         struct trace_event_call *call, *p;
2215         const char *last_system =3D NULL;
2216         int last_i;
2217         int i;
2218=20
2219         down_write(&trace_event_sem);
2220         list_for_each_entry_safe(call, p, &ftrace_events, list) {
2221                 /* events are usually grouped together with systems =
*/
2222                 if (!last_system || call->class->system !=3D =
last_system) {
2223                         last_i =3D 0;
2224                         last_system =3D call->class->system;
2225                 }
2226=20
2227                 for (i =3D last_i; i < len; i++) {
2228                         if (call->class->system =3D=3D =
map[i]->system) {
2229                                 /* Save the first system if need be =
*/
2230                                 if (!last_i)
2231                                         last_i =3D i;
2232                                 update_event_printk(call, map[i]);
2233                         }
2234                 }
2235         }
2236         up_write(&trace_event_sem);
2237 }

Loading the nfs.ko module adds an eval map consisting of three entries:

entry 0 is NFS_FILE_SYNC with a value of 2
entry 1 is NFS_DATA_SYNC with a value of 1
entry 2 is NFS_UNSTABLE with a value of 0

The nfs.ko trace point print_fmt strings are updated by
trace_event_eval_update.

For the first trace point in nfs.ko, the first iteration of the inner
loop visits all three of these map entries, but it's print_fmt does
not contain any of these enum symbols, so nothing changes.

Now thanks to the "last_i" logic above, entry 0 (NFS_FILE_SYNC) is
skipped over for other trace points in the module.

Thus when the print_fmt strings for "nfs_initiate_write" and
"nfs_writeback_done" are updated, they are only partially converted,
hence:

> "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld count=3D%lu =
stable=3D%d (%s)", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) =
((REC->dev) & ((1U << 20) - 1))), (unsigned long long)REC->fileid, =
REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, "NFS_UNSTABLE" }, { 1, =
"NFS_DATA_SYNC" }, { NFS_FILE_SYNC, "NFS_FILE_SYNC" })


The updated string contains integers for the first two items in the
symbol table, and has an unconverted third item, which cannot be used
by "trace-cmd report".

Adding another TRACE_DEFINE_ENUM in fs/nfs/nfstrace.h works around
this issue. I added

TRACE_DEFINE_ENUM(NFS_INVALID_STABLE_HOW);

_after_ the first three, and that became entry 0 in the nfs system
eval_map. That entry is unusable due to this bug, but I didn't add
it to any trace points. The updated print_fmt strings are now 100%
correct. "trace-cmd report" works exactly as intended.

My inclination is to remove the last_i logic from this function, but
I don't understand what the last_system/last_i logic is attempting
accomplish. Do you have any suggestions?


--
Chuck Lever

Re: odd TRACE_DEFINE_ENUM behavior

[Steven Rostedt]

On Wed, 17 Jan 2018 16:13:27 -0500
Chuck Lever <chuck.lever@oracle.com> wrote:

> 
> The problem is in this function (kernel/trace/trace_events.c):
> 
> 2212 void trace_event_eval_update(struct trace_eval_map **map, int len)
> 2213 {
> 2214         struct trace_event_call *call, *p;
> 2215         const char *last_system = NULL;
> 2216         int last_i;
> 2217         int i;
> 2218 
> 2219         down_write(&trace_event_sem);
> 2220         list_for_each_entry_safe(call, p, &ftrace_events, list) {
> 2221                 /* events are usually grouped together with systems */
> 2222                 if (!last_system || call->class->system != last_system) {
> 2223                         last_i = 0;
> 2224                         last_system = call->class->system;
> 2225                 }
> 2226 
> 2227                 for (i = last_i; i < len; i++) {
> 2228                         if (call->class->system == map[i]->system) {
> 2229                                 /* Save the first system if need be */
> 2230                                 if (!last_i)
> 2231                                         last_i = i;
> 2232                                 update_event_printk(call, map[i]);
> 2233                         }
> 2234                 }
> 2235         }
> 2236         up_write(&trace_event_sem);
> 2237 }
> 
> Loading the nfs.ko module adds an eval map consisting of three entries:
> 
> entry 0 is NFS_FILE_SYNC with a value of 2
> entry 1 is NFS_DATA_SYNC with a value of 1
> entry 2 is NFS_UNSTABLE with a value of 0
> 
> The nfs.ko trace point print_fmt strings are updated by
> trace_event_eval_update.
> 
> For the first trace point in nfs.ko, the first iteration of the inner
> loop visits all three of these map entries, but it's print_fmt does
> not contain any of these enum symbols, so nothing changes.
> 
> Now thanks to the "last_i" logic above, entry 0 (NFS_FILE_SYNC) is
> skipped over for other trace points in the module.
> 
> Thus when the print_fmt strings for "nfs_initiate_write" and
> "nfs_writeback_done" are updated, they are only partially converted,
> hence:
> 
> > "fileid=%02x:%02x:%llu fhandle=0x%08x offset=%lld count=%lu stable=%d (%s)", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long long)REC->fileid, REC->fhandle, REC->offset, REC->count, REC->stable, __print_symbolic(REC->stable, { 0, "NFS_UNSTABLE" }, { 1, "NFS_DATA_SYNC" }, { NFS_FILE_SYNC, "NFS_FILE_SYNC" })  
> 
> 
> The updated string contains integers for the first two items in the
> symbol table, and has an unconverted third item, which cannot be used
> by "trace-cmd report".
> 
> Adding another TRACE_DEFINE_ENUM in fs/nfs/nfstrace.h works around
> this issue. I added
> 
> TRACE_DEFINE_ENUM(NFS_INVALID_STABLE_HOW);
> 
> _after_ the first three, and that became entry 0 in the nfs system
> eval_map. That entry is unusable due to this bug, but I didn't add
> it to any trace points. The updated print_fmt strings are now 100%
> correct. "trace-cmd report" works exactly as intended.
> 
> My inclination is to remove the last_i logic from this function, but
> I don't understand what the last_system/last_i logic is attempting
> accomplish. Do you have any suggestions?

Nice detective work. I see the bug.

The last_i is an optimization to not have to search the entire map
array for the first matching map[i].system every time. But the bug is,
if the match is on the first hit (i==0) then we set last_i to 0, and on
the next iteration we set it (incorrectly) to 1. That's the bug.

Can you try this patch?

I'll have to add comments to that function, as it took me too long to
figure out WTF I was thinking when I wrote it.

-- Steve

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index ec0f9aa4e151..9b5b8a362690 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2213,6 +2213,7 @@ void trace_event_eval_update(struct trace_eval_map **map, int len)
 {
 	struct trace_event_call *call, *p;
 	const char *last_system = NULL;
+	bool first = false;
 	int last_i;
 	int i;
 
@@ -2220,6 +2221,7 @@ void trace_event_eval_update(struct trace_eval_map **map, int len)
 	list_for_each_entry_safe(call, p, &ftrace_events, list) {
 		/* events are usually grouped together with systems */
 		if (!last_system || call->class->system != last_system) {
+			first = true;
 			last_i = 0;
 			last_system = call->class->system;
 		}
@@ -2227,8 +2229,10 @@ void trace_event_eval_update(struct trace_eval_map **map, int len)
 		for (i = last_i; i < len; i++) {
 			if (call->class->system == map[i]->system) {
 				/* Save the first system if need be */
-				if (!last_i)
+				if (first) {
 					last_i = i;
+					first = false;
+				}
 				update_event_printk(call, map[i]);
 			}
 		}

Re: odd TRACE_DEFINE_ENUM behavior

[Chuck Lever]

> On Jan 17, 2018, at 10:01 PM, Steven Rostedt <rostedt@goodmis.org> =
wrote:
>=20
> On Wed, 17 Jan 2018 16:13:27 -0500
> Chuck Lever <chuck.lever@oracle.com> wrote:
>=20
>>=20
>> The problem is in this function (kernel/trace/trace_events.c):
>>=20
>> 2212 void trace_event_eval_update(struct trace_eval_map **map, int =
len)
>> 2213 {
>> 2214         struct trace_event_call *call, *p;
>> 2215         const char *last_system =3D NULL;
>> 2216         int last_i;
>> 2217         int i;
>> 2218=20
>> 2219         down_write(&trace_event_sem);
>> 2220         list_for_each_entry_safe(call, p, &ftrace_events, list) =
{
>> 2221                 /* events are usually grouped together with =
systems */
>> 2222                 if (!last_system || call->class->system !=3D =
last_system) {
>> 2223                         last_i =3D 0;
>> 2224                         last_system =3D call->class->system;
>> 2225                 }
>> 2226=20
>> 2227                 for (i =3D last_i; i < len; i++) {
>> 2228                         if (call->class->system =3D=3D =
map[i]->system) {
>> 2229                                 /* Save the first system if need =
be */
>> 2230                                 if (!last_i)
>> 2231                                         last_i =3D i;
>> 2232                                 update_event_printk(call, =
map[i]);
>> 2233                         }
>> 2234                 }
>> 2235         }
>> 2236         up_write(&trace_event_sem);
>> 2237 }
>>=20
>> Loading the nfs.ko module adds an eval map consisting of three =
entries:
>>=20
>> entry 0 is NFS_FILE_SYNC with a value of 2
>> entry 1 is NFS_DATA_SYNC with a value of 1
>> entry 2 is NFS_UNSTABLE with a value of 0
>>=20
>> The nfs.ko trace point print_fmt strings are updated by
>> trace_event_eval_update.
>>=20
>> For the first trace point in nfs.ko, the first iteration of the inner
>> loop visits all three of these map entries, but it's print_fmt does
>> not contain any of these enum symbols, so nothing changes.
>>=20
>> Now thanks to the "last_i" logic above, entry 0 (NFS_FILE_SYNC) is
>> skipped over for other trace points in the module.
>>=20
>> Thus when the print_fmt strings for "nfs_initiate_write" and
>> "nfs_writeback_done" are updated, they are only partially converted,
>> hence:
>>=20
>>> "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld count=3D%lu =
stable=3D%d (%s)", ((unsigned int) ((REC->dev) >> 20)), ((unsigned int) =
((REC->dev) & ((1U << 20) - 1))), (unsigned long long)REC->fileid, =
REC->fhandle, REC->offset, REC->count, REC->stable, =
__print_symbolic(REC->stable, { 0, "NFS_UNSTABLE" }, { 1, =
"NFS_DATA_SYNC" }, { NFS_FILE_SYNC, "NFS_FILE_SYNC" }) =20
>>=20
>>=20
>> The updated string contains integers for the first two items in the
>> symbol table, and has an unconverted third item, which cannot be used
>> by "trace-cmd report".
>>=20
>> Adding another TRACE_DEFINE_ENUM in fs/nfs/nfstrace.h works around
>> this issue. I added
>>=20
>> TRACE_DEFINE_ENUM(NFS_INVALID_STABLE_HOW);
>>=20
>> _after_ the first three, and that became entry 0 in the nfs system
>> eval_map. That entry is unusable due to this bug, but I didn't add
>> it to any trace points. The updated print_fmt strings are now 100%
>> correct. "trace-cmd report" works exactly as intended.
>>=20
>> My inclination is to remove the last_i logic from this function, but
>> I don't understand what the last_system/last_i logic is attempting
>> accomplish. Do you have any suggestions?
>=20
> Nice detective work. I see the bug.
>=20
> The last_i is an optimization to not have to search the entire map
> array for the first matching map[i].system every time. But the bug is,
> if the match is on the first hit (i=3D=3D0) then we set last_i to 0, =
and on
> the next iteration we set it (incorrectly) to 1. That's the bug.
>=20
> Can you try this patch?
>=20
> I'll have to add comments to that function, as it took me too long to
> figure out WTF I was thinking when I wrote it.
>=20
> -- Steve
>=20
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index ec0f9aa4e151..9b5b8a362690 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -2213,6 +2213,7 @@ void trace_event_eval_update(struct =
trace_eval_map **map, int len)
> {
> 	struct trace_event_call *call, *p;
> 	const char *last_system =3D NULL;
> +	bool first =3D false;
> 	int last_i;
> 	int i;
>=20
> @@ -2220,6 +2221,7 @@ void trace_event_eval_update(struct =
trace_eval_map **map, int len)
> 	list_for_each_entry_safe(call, p, &ftrace_events, list) {
> 		/* events are usually grouped together with systems */
> 		if (!last_system || call->class->system !=3D =
last_system) {
> +			first =3D true;
> 			last_i =3D 0;
> 			last_system =3D call->class->system;
> 		}
> @@ -2227,8 +2229,10 @@ void trace_event_eval_update(struct =
trace_eval_map **map, int len)
> 		for (i =3D last_i; i < len; i++) {
> 			if (call->class->system =3D=3D map[i]->system) {
> 				/* Save the first system if need be */
> -				if (!last_i)
> +				if (first) {
> 					last_i =3D i;
> +					first =3D false;
> +				}
> 				update_event_printk(call, map[i]);
> 			}
> 		}

Thanks for the patch! I removed the workaround:

  TRACE_DEFINE_ENUM(NFS_INVALID_STABLE_HOW);

and applied the above patch. I'd say the fix passes the test:

[root@manet ~]# cat =
/sys/kernel/debug/tracing/events/nfs/nfs_initiate_write/format
name: nfs_initiate_write
ID: 1819
format:
	field:unsigned short common_type;	offset:0;	size:2;	=
signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	=
signed:0;
	field:unsigned char common_preempt_count;	offset:3;	=
size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:loff_t offset;	offset:8;	size:8;	signed:1;
	field:unsigned long count;	offset:16;	size:8;	=
signed:0;
	field:enum nfs3_stable_how stable;	offset:24;	size:4;	=
signed:1;
	field:dev_t dev;	offset:28;	size:4;	signed:0;
	field:u32 fhandle;	offset:32;	size:4;	signed:0;
	field:u64 fileid;	offset:40;	size:8;	signed:0;

print fmt: "fileid=3D%02x:%02x:%llu fhandle=3D0x%08x offset=3D%lld =
count=3D%lu stable=3D%s", ((unsigned int) ((REC->dev) >> 20)), =
((unsigned int) ((REC->dev) & ((1U << 20) - 1))), (unsigned long =
long)REC->fileid, REC->fhandle, REC->offset, REC->count, =
__print_symbolic(REC->stable, { 0, "UNSTABLE" }, { 1, "DATA_SYNC" }, { =
2, "FILE_SYNC" })
[root@manet ~]#=20

And "trace-cmd report" output appears as expected.

Tested-by: Chuck Lever <chuck.lever@oracle.com>


--
Chuck Lever