* [LTP] [PATCH] clock_gettime04: print more info to help debugging
@ 2021-03-08 6:53 Li Wang
2021-03-08 10:17 ` Viresh Kumar
0 siblings, 1 reply; 8+ messages in thread
From: Li Wang @ 2021-03-08 6:53 UTC (permalink / raw)
To: ltp
We get some sporadically failures like below, but we don't know which
loop it comes from. So adding more prints to help locate issue.
tst_test.c:1286: TINFO: Timeout per run is 0h 05m 00s
vdso_helpers.c:76: TINFO: Couldn't find vdso_gettime64()
clock_gettime04.c:157: TPASS: CLOCK_REALTIME: Difference between successive readings is reasonable
clock_gettime04.c:150: TFAIL: CLOCK_REALTIME_COARSE: Difference between successive readings greater than 5 ms (1): 8
clock_gettime04.c:157: TPASS: CLOCK_MONOTONIC: Difference between successive readings is reasonable
clock_gettime04.c:150: TFAIL: CLOCK_MONOTONIC_COARSE: Difference between successive readings greater than 5 ms (0): 5
clock_gettime04.c:157: TPASS: CLOCK_MONOTONIC_RAW: Difference between successive readings is reasonable
clock_gettime04.c:157: TPASS: CLOCK_BOOTTIME: Difference between successive readings is reasonable
Btw, it occurs on a x86_64 (not virtualized) with kernel 5.11.0.
Signed-off-by: Li Wang <liwang@redhat.com>
---
testcases/kernel/syscalls/clock_gettime/clock_gettime04.c | 3 +++
1 file changed, 3 insertions(+)
diff --git a/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c b/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
index 5f8264cc6..4dc9093c7 100644
--- a/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
+++ b/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
@@ -108,6 +108,9 @@ static void run(unsigned int i)
if (tv->clock_gettime == my_gettimeofday && clks[i] != CLOCK_REALTIME)
continue;
+ if (tv->clock_gettime && count == 10000)
+ tst_res(TINFO, "%s", tv->desc);
+
ret = tv->clock_gettime(clks[i], tst_ts_get(&ts));
if (ret) {
/*
--
2.21.3
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [LTP] [PATCH] clock_gettime04: print more info to help debugging
2021-03-08 6:53 [LTP] [PATCH] clock_gettime04: print more info to help debugging Li Wang
@ 2021-03-08 10:17 ` Viresh Kumar
2021-03-08 10:59 ` Li Wang
0 siblings, 1 reply; 8+ messages in thread
From: Viresh Kumar @ 2021-03-08 10:17 UTC (permalink / raw)
To: ltp
On 08-03-21, 06:53, Li Wang wrote:
> We get some sporadically failures like below, but we don't know which
> loop it comes from. So adding more prints to help locate issue.
>
> tst_test.c:1286: TINFO: Timeout per run is 0h 05m 00s
> vdso_helpers.c:76: TINFO: Couldn't find vdso_gettime64()
> clock_gettime04.c:157: TPASS: CLOCK_REALTIME: Difference between successive readings is reasonable
> clock_gettime04.c:150: TFAIL: CLOCK_REALTIME_COARSE: Difference between successive readings greater than 5 ms (1): 8
> clock_gettime04.c:157: TPASS: CLOCK_MONOTONIC: Difference between successive readings is reasonable
> clock_gettime04.c:150: TFAIL: CLOCK_MONOTONIC_COARSE: Difference between successive readings greater than 5 ms (0): 5
> clock_gettime04.c:157: TPASS: CLOCK_MONOTONIC_RAW: Difference between successive readings is reasonable
> clock_gettime04.c:157: TPASS: CLOCK_BOOTTIME: Difference between successive readings is reasonable
>
> Btw, it occurs on a x86_64 (not virtualized) with kernel 5.11.0.
>
> Signed-off-by: Li Wang <liwang@redhat.com>
> ---
> testcases/kernel/syscalls/clock_gettime/clock_gettime04.c | 3 +++
> 1 file changed, 3 insertions(+)
>
> diff --git a/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c b/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
> index 5f8264cc6..4dc9093c7 100644
> --- a/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
> +++ b/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
> @@ -108,6 +108,9 @@ static void run(unsigned int i)
> if (tv->clock_gettime == my_gettimeofday && clks[i] != CLOCK_REALTIME)
> continue;
>
> + if (tv->clock_gettime && count == 10000)
clock_gettime will always be valid here, isn't it ?
> + tst_res(TINFO, "%s", tv->desc);
> +
I think you just need to add this to setup(), same is done for various
tests already.
tst_res(TINFO, "Testing variant: %s", variants[tst_variant].desc);
--
viresh
^ permalink raw reply [flat|nested] 8+ messages in thread
* [LTP] [PATCH] clock_gettime04: print more info to help debugging
2021-03-08 10:17 ` Viresh Kumar
@ 2021-03-08 10:59 ` Li Wang
2021-03-08 11:14 ` Viresh Kumar
0 siblings, 1 reply; 8+ messages in thread
From: Li Wang @ 2021-03-08 10:59 UTC (permalink / raw)
To: ltp
On Mon, Mar 8, 2021 at 6:17 PM Viresh Kumar <viresh.kumar@linaro.org> wrote:
> On 08-03-21, 06:53, Li Wang wrote:
> > We get some sporadically failures like below, but we don't know which
> > loop it comes from. So adding more prints to help locate issue.
> >
> > tst_test.c:1286: TINFO: Timeout per run is 0h 05m 00s
> > vdso_helpers.c:76: TINFO: Couldn't find vdso_gettime64()
> > clock_gettime04.c:157: TPASS: CLOCK_REALTIME: Difference between
> successive readings is reasonable
> > clock_gettime04.c:150: TFAIL: CLOCK_REALTIME_COARSE: Difference
> between successive readings greater than 5 ms (1): 8
> > clock_gettime04.c:157: TPASS: CLOCK_MONOTONIC: Difference between
> successive readings is reasonable
> > clock_gettime04.c:150: TFAIL: CLOCK_MONOTONIC_COARSE: Difference
> between successive readings greater than 5 ms (0): 5
> > clock_gettime04.c:157: TPASS: CLOCK_MONOTONIC_RAW: Difference between
> successive readings is reasonable
> > clock_gettime04.c:157: TPASS: CLOCK_BOOTTIME: Difference between
> successive readings is reasonable
> >
> > Btw, it occurs on a x86_64 (not virtualized) with kernel 5.11.0.
> >
> > Signed-off-by: Li Wang <liwang@redhat.com>
> > ---
> > testcases/kernel/syscalls/clock_gettime/clock_gettime04.c | 3 +++
> > 1 file changed, 3 insertions(+)
> >
> > diff --git a/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
> b/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
> > index 5f8264cc6..4dc9093c7 100644
> > --- a/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
> > +++ b/testcases/kernel/syscalls/clock_gettime/clock_gettime04.c
> > @@ -108,6 +108,9 @@ static void run(unsigned int i)
> > if (tv->clock_gettime == my_gettimeofday &&
> clks[i] != CLOCK_REALTIME)
> > continue;
> >
> > + if (tv->clock_gettime && count == 10000)
>
> clock_gettime will always be valid here, isn't it ?
>
Yes, but that's not harmful. If you remove all entries of varaints[] you can
still get PASS from the test, that's something strange to us. So I just add
this check there.
>
> > + tst_res(TINFO, "%s", tv->desc);
> > +
>
> I think you just need to add this to setup(), same is done for various
> tests already.
>
No, that will only print the first entry instruct variants because you're
using two iterations in the run(), the second loop 'j' is to traverse the
variants[] actually.
>
> tst_res(TINFO, "Testing variant: %s", variants[tst_variant].desc);
>
> --
> viresh
>
>
--
Regards,
Li Wang
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20210308/603d0d14/attachment.htm>
^ permalink raw reply [flat|nested] 8+ messages in thread
* [LTP] [PATCH] clock_gettime04: print more info to help debugging
2021-03-08 10:59 ` Li Wang
@ 2021-03-08 11:14 ` Viresh Kumar
2021-03-08 11:24 ` Li Wang
0 siblings, 1 reply; 8+ messages in thread
From: Viresh Kumar @ 2021-03-08 11:14 UTC (permalink / raw)
To: ltp
On 08-03-21, 18:59, Li Wang wrote:
> Yes, but that's not harmful.
But is useless.
> If you remove all entries of varaints[] you can
> still get PASS from the test, that's something strange to us. So I just add
> this check there.
Yes, that would happen because we will not run the inner loop in that
case and even the condition you are adding will not run at all.
This wasn't designed to run with empty variants list and so we don't
verify that variants structure is empty or not and so it passes.
> No, that will only print the first entry instruct variants because you're
> using two iterations in the run(), the second loop 'j' is to traverse the
> variants[] actually.
Ahh, my bad. I didn't read the code properly. Sorry about that.
Now that I had a look again, with what you are adding here we will
start printing another line for each variant and it will be printed
just once at the beginning of the loop of 10000 iterations. Right ?
I am not sure how that will help you get more info out, to me it is
still very much unreadable. Can you show the final output as well ?
What about adding tv->desc to all the existing print messages instead
? Or maybe just the TFAIL ones? So we print everything in a single
line only ?
--
viresh
^ permalink raw reply [flat|nested] 8+ messages in thread
* [LTP] [PATCH] clock_gettime04: print more info to help debugging
2021-03-08 11:14 ` Viresh Kumar
@ 2021-03-08 11:24 ` Li Wang
2021-03-08 11:48 ` Viresh Kumar
0 siblings, 1 reply; 8+ messages in thread
From: Li Wang @ 2021-03-08 11:24 UTC (permalink / raw)
To: ltp
On Mon, Mar 8, 2021 at 7:14 PM Viresh Kumar <viresh.kumar@linaro.org> wrote:
> On 08-03-21, 18:59, Li Wang wrote:
> > Yes, but that's not harmful.
>
> But is useless.
>
> > If you remove all entries of varaints[] you can
> > still get PASS from the test, that's something strange to us. So I just
> add
> > this check there.
>
> Yes, that would happen because we will not run the inner loop in that
> case and even the condition you are adding will not run at all.
>
> This wasn't designed to run with empty variants list and so we don't
> verify that variants structure is empty or not and so it passes.
>
Indeed. I agree to remove 'tv->clock_gettime' check.
>
> > No, that will only print the first entry instruct variants because you're
> > using two iterations in the run(), the second loop 'j' is to traverse the
> > variants[] actually.
>
> Ahh, my bad. I didn't read the code properly. Sorry about that.
>
> Now that I had a look again, with what you are adding here we will
> start printing another line for each variant and it will be printed
> just once at the beginning of the loop of 10000 iterations. Right ?
>
Right.
>
> I am not sure how that will help you get more info out, to me it is
> still very much unreadable. Can you show the final output as well ?
>
# ./clock_gettime04
tst_test.c:1288: TINFO: Timeout per run is 0h 05m 00s
clock_gettime04.c:84: TINFO: Running in a virtual machine, multiply the
delta by 10.
vdso_helpers.c:76: TINFO: Couldn't find vdso_gettime64()
clock_gettime04.c:158: TPASS: CLOCK_REALTIME: Difference between successive
readings is reasonable
clock_gettime04.c:158: TPASS: CLOCK_REALTIME_COARSE: Difference between
successive readings is reasonable
clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC: Difference between
successive readings is reasonable
clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC_COARSE: Difference between
successive readings is reasonable
clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC_RAW: Difference between
successive readings is reasonable
clock_gettime04.c:158: TPASS: CLOCK_BOOTTIME: Difference between successive
readings is reasonable
After my patch:
# ./clock_gettime04
tst_test.c:1288: TINFO: Timeout per run is 0h 05m 00s
clock_gettime04.c:84: TINFO: Running in a virtual machine, multiply the
delta by 10.
vdso_helpers.c:76: TINFO: Couldn't find vdso_gettime64()
clock_gettime04.c:112: TINFO: vDSO or syscall with libc spec
clock_gettime04.c:112: TINFO: syscall with old kernel spec
clock_gettime04.c:112: TINFO: vDSO with old kernel spec
clock_gettime04.c:112: TINFO: gettimeofday
clock_gettime04.c:160: TPASS: CLOCK_REALTIME: Difference between successive
readings is reasonable
clock_gettime04.c:112: TINFO: vDSO or syscall with libc spec
clock_gettime04.c:112: TINFO: syscall with old kernel spec
clock_gettime04.c:112: TINFO: vDSO with old kernel spec
clock_gettime04.c:160: TPASS: CLOCK_REALTIME_COARSE: Difference between
successive readings is reasonable
clock_gettime04.c:112: TINFO: vDSO or syscall with libc spec
clock_gettime04.c:112: TINFO: syscall with old kernel spec
clock_gettime04.c:112: TINFO: vDSO with old kernel spec
clock_gettime04.c:160: TPASS: CLOCK_MONOTONIC: Difference between
successive readings is reasonable
clock_gettime04.c:112: TINFO: vDSO or syscall with libc spec
clock_gettime04.c:112: TINFO: syscall with old kernel spec
clock_gettime04.c:112: TINFO: vDSO with old kernel spec
clock_gettime04.c:160: TPASS: CLOCK_MONOTONIC_COARSE: Difference between
successive readings is reasonable
clock_gettime04.c:112: TINFO: vDSO or syscall with libc spec
clock_gettime04.c:112: TINFO: syscall with old kernel spec
clock_gettime04.c:112: TINFO: vDSO with old kernel spec
clock_gettime04.c:160: TPASS: CLOCK_MONOTONIC_RAW: Difference between
successive readings is reasonable
clock_gettime04.c:112: TINFO: vDSO or syscall with libc spec
clock_gettime04.c:112: TINFO: syscall with old kernel spec
clock_gettime04.c:112: TINFO: vDSO with old kernel spec
clock_gettime04.c:160: TPASS: CLOCK_BOOTTIME: Difference between successive
readings is reasonable
>
> What about adding tv->desc to all the existing print messages instead
> ? Or maybe just the TFAIL ones? So we print everything in a single
> line only ?
>
But that still not good enough.
e.g
In PASS status, we missing some details.
>
> --
> viresh
>
>
--
Regards,
Li Wang
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20210308/aae2314a/attachment.htm>
^ permalink raw reply [flat|nested] 8+ messages in thread
* [LTP] [PATCH] clock_gettime04: print more info to help debugging
2021-03-08 11:24 ` Li Wang
@ 2021-03-08 11:48 ` Viresh Kumar
2021-03-08 12:45 ` Li Wang
0 siblings, 1 reply; 8+ messages in thread
From: Viresh Kumar @ 2021-03-08 11:48 UTC (permalink / raw)
To: ltp
On 08-03-21, 19:24, Li Wang wrote:
> # ./clock_gettime04
> tst_test.c:1288: TINFO: Timeout per run is 0h 05m 00s
> clock_gettime04.c:84: TINFO: Running in a virtual machine, multiply the
> delta by 10.
> vdso_helpers.c:76: TINFO: Couldn't find vdso_gettime64()
> clock_gettime04.c:158: TPASS: CLOCK_REALTIME: Difference between successive
> readings is reasonable
> clock_gettime04.c:158: TPASS: CLOCK_REALTIME_COARSE: Difference between
> successive readings is reasonable
> clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC: Difference between
> successive readings is reasonable
> clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC_COARSE: Difference between
> successive readings is reasonable
> clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC_RAW: Difference between
> successive readings is reasonable
> clock_gettime04.c:158: TPASS: CLOCK_BOOTTIME: Difference between successive
> readings is reasonable
>
>
> After my patch:
>
> # ./clock_gettime04
> tst_test.c:1288: TINFO: Timeout per run is 0h 05m 00s
> clock_gettime04.c:84: TINFO: Running in a virtual machine, multiply the
> delta by 10.
> vdso_helpers.c:76: TINFO: Couldn't find vdso_gettime64()
> clock_gettime04.c:112: TINFO: vDSO or syscall with libc spec
> clock_gettime04.c:112: TINFO: syscall with old kernel spec
> clock_gettime04.c:112: TINFO: vDSO with old kernel spec
> clock_gettime04.c:112: TINFO: gettimeofday
The above doesn't look nice TBH.
> clock_gettime04.c:160: TPASS: CLOCK_REALTIME: Difference between successive
> readings is reasonable
>
> >
> > What about adding tv->desc to all the existing print messages instead
> > ? Or maybe just the TFAIL ones? So we print everything in a single
> > line only ?
> >
>
> But that still not good enough.
> e.g
> In PASS status, we missing some details.
Hmm, so there are two loops we are running here. One is for each CLOCK
and one for each variant. And the final PASS message only talks about
the CLOCK type and there is nothing about variants..
Lets decide how we want the output message to look and then code can
be changed accordingly.
Option 1: Just like what we have right now.
clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC: Difference between
successive readings is reasonable
Option 2: Separate line for each variant.
clock_gettime04.c:158: TPASS: vDSO or syscall with libc spec: CLOCK_MONOTONIC: Difference between successive readings is reasonable
clock_gettime04.c:158: TPASS: syscall with old kernel spec : CLOCK_MONOTONIC: Difference between successive readings is reasonable
clock_gettime04.c:158: TPASS: vDSO with old kernel spec : CLOCK_MONOTONIC: Difference between successive readings is reasonable
clock_gettime04.c:158: TPASS: gettimeofday : CLOCK_MONOTONIC: Difference between successive readings is reasonable
Option 3: Same as option 2 but different formatting
clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC: Difference between successive readings is reasonable for following variants:
- vDSO or syscall with libc spec
- syscall with old kernel spec
- vDSO with old kernel spec
- gettimeofday
Any other option here ?
For the FAIL messages, I think just adding tv->desc is good enough.
--
viresh
^ permalink raw reply [flat|nested] 8+ messages in thread
* [LTP] [PATCH] clock_gettime04: print more info to help debugging
2021-03-08 11:48 ` Viresh Kumar
@ 2021-03-08 12:45 ` Li Wang
2021-03-09 4:05 ` Viresh Kumar
0 siblings, 1 reply; 8+ messages in thread
From: Li Wang @ 2021-03-08 12:45 UTC (permalink / raw)
To: ltp
Viresh Kumar <viresh.kumar@linaro.org> wrote:
...
>
> Option 3: Same as option 2 but different formatting
>
> clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC: Difference between
> successive readings is reasonable for following variants:
> - vDSO or syscall with libc spec
> - syscall with old kernel spec
> - vDSO with old kernel spec
> - gettimeofday
Any other option here ?
>
I think no.
>
> For the FAIL messages, I think just adding tv->desc is good enough.
>
+1, I prefer to go with Option3 + 'tv->desc for FAIL'.
Would you mind formatting a patch, or I can do that?
--
Regards,
Li Wang
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.linux.it/pipermail/ltp/attachments/20210308/45e21897/attachment.htm>
^ permalink raw reply [flat|nested] 8+ messages in thread
* [LTP] [PATCH] clock_gettime04: print more info to help debugging
2021-03-08 12:45 ` Li Wang
@ 2021-03-09 4:05 ` Viresh Kumar
0 siblings, 0 replies; 8+ messages in thread
From: Viresh Kumar @ 2021-03-09 4:05 UTC (permalink / raw)
To: ltp
On 08-03-21, 20:45, Li Wang wrote:
> Viresh Kumar <viresh.kumar@linaro.org> wrote:
>
> ...
> >
> > Option 3: Same as option 2 but different formatting
> >
> > clock_gettime04.c:158: TPASS: CLOCK_MONOTONIC: Difference between
> > successive readings is reasonable for following variants:
> > - vDSO or syscall with libc spec
> > - syscall with old kernel spec
> > - vDSO with old kernel spec
> > - gettimeofday
>
> Any other option here ?
> >
>
> I think no.
>
> >
> > For the FAIL messages, I think just adding tv->desc is good enough.
> >
>
> +1, I prefer to go with Option3 + 'tv->desc for FAIL'.
>
> Would you mind formatting a patch, or I can do that?
Since you started it, I will let you finish it as well :)
Thanks.
--
viresh
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2021-03-09 4:05 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-03-08 6:53 [LTP] [PATCH] clock_gettime04: print more info to help debugging Li Wang
2021-03-08 10:17 ` Viresh Kumar
2021-03-08 10:59 ` Li Wang
2021-03-08 11:14 ` Viresh Kumar
2021-03-08 11:24 ` Li Wang
2021-03-08 11:48 ` Viresh Kumar
2021-03-08 12:45 ` Li Wang
2021-03-09 4:05 ` Viresh Kumar
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.