| Message ID | 20210308065329.25824-1-liwang@redhat.com |
|---|---|
| State | Changes Requested |
| Headers | show |
| Series | clock_gettime04: print more info to help debugging | expand |
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);
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 > >
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 ?
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 > >
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 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?
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.
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) { /*
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(+)