Re: [Qemu-devel] regression in timer code?

[Max Filippov]

On Wed, Mar 14, 2018 at 11:09 PM, Pavel Dovgalyuk  wrote:
>> From: Max Filippov [mailto:jcmvb...@gmail.com]
>> On Wed, Mar 14, 2018 at 2:53 AM, Pavel Dovgalyuk  wrote:
>> > icount is adjusted by icount_warp_rt when CPU sleeps.
>> > These adjustments may be different in different runs.
>> > And the first adjustment is performed at the start of the machine.
>> > Therefore "now" value includes non-deterministic component from the 
>> > beginning,
>> > but its increments caused by instruction executions are deterministic.
>>
>> Ok, so the CPU reset is non-deterministic. Thanks.
>
> BTW, your link to website in MAINTAINERS does not work.
>
> W: http://wiki.osll.spb.ru/doku.php?id=etc:users:jcmvbkbc:qemu-target-xtensa

I know, thank you. There's a fix queued for it:
  http://lists.nongnu.org/archive/html/qemu-devel/2018-02/msg07346.html

-- 
Thanks.
-- Max

Re: [Qemu-devel] regression in timer code?

[Pavel Dovgalyuk]

> From: Max Filippov [mailto:jcmvb...@gmail.com]
> On Wed, Mar 14, 2018 at 2:53 AM, Pavel Dovgalyuk  wrote:
> > icount is adjusted by icount_warp_rt when CPU sleeps.
> > These adjustments may be different in different runs.
> > And the first adjustment is performed at the start of the machine.
> > Therefore "now" value includes non-deterministic component from the 
> > beginning,
> > but its increments caused by instruction executions are deterministic.
> 
> Ok, so the CPU reset is non-deterministic. Thanks.

BTW, your link to website in MAINTAINERS does not work.

W: http://wiki.osll.spb.ru/doku.php?id=etc:users:jcmvbkbc:qemu-target-xtensa


Pavel Dovgalyuk

Re: [Qemu-devel] regression in timer code?

[Max Filippov]

On Wed, Mar 14, 2018 at 2:53 AM, Pavel Dovgalyuk  wrote:
> icount is adjusted by icount_warp_rt when CPU sleeps.
> These adjustments may be different in different runs.
> And the first adjustment is performed at the start of the machine.
> Therefore "now" value includes non-deterministic component from the beginning,
> but its increments caused by instruction executions are deterministic.

Ok, so the CPU reset is non-deterministic. Thanks.

-- Max

Re: [Qemu-devel] regression in timer code?

[Pavel Dovgalyuk]

> -Original Message-
> From: Max Filippov [mailto:jcmvb...@gmail.com]
> Sent: Wednesday, March 14, 2018 12:41 PM
> To: Pavel Dovgalyuk
> Cc: Pavel Dovgaluk; qemu-devel
> Subject: Re: regression in timer code?
> 
> On Wed, Mar 14, 2018 at 2:07 AM, Pavel Dovgalyuk  wrote:
> >> From: Max Filippov [mailto:jcmvb...@gmail.com]
> >> the commit b39e3f34c9de7ead6a11a74aa2de78baf41d81a7
> >> ("icount: fixed saving/restoring of icount warp timers") has changed
> >> something that made timers test for target/xtensa unstable.
> >> Specifically ccount_write case in the tests/tcg/xtensa/test_timer.S
> >> now fails for me about half of the times it is run. Given that it is run
> >> under -icount I guess this is a bug. Could you please take a look?
> >>
> >> The minimal test case is available here:
> >>   http://jcmvbkbc.spb.ru/~dumb/tmp/201803131306/test_timer.tst
> >> It is run as
> >>   qemu-system-xtensa -M sim -cpu dc232b -nographic -semihosting
> >> -icount 7  -kernel ./test_timer.tst
> >
> > I investigated your test and concluded the following.
> > First, update_ccount is inaccurate opration because of the division
> > with the remainder:
> > env->sregs[CCOUNT] = env->ccount_base +
> > (uint32_t)((now - env->time_base) *
> >env->config->clock_freq_khz / 100);
> >
> > Therefore, the following sequence in the test may give different result 
> > depending
> > of the actual value of "now" variable.
> 
> But the expression above depends on the difference between the now
> and env->time_base, both these values are read from
>  qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) and, most importantly,
> the test is 100% deterministic, i.e. it runs under -icount and there's no
> external factors involved, no waiting for anything, not even interrupts.
> Thus the difference must be constant, i.e. I must see consistent results.
> Am I wrong somewhere?

icount is adjusted by icount_warp_rt when CPU sleeps.
These adjustments may be different in different runs.
And the first adjustment is performed at the start of the machine.
Therefore "now" value includes non-deterministic component from the beginning,
but its increments caused by instruction executions are deterministic.

> > rsr a3, ccount
> > rsr a4, ccount
> > sub a4, a4, a3
> >
> > Consider the code:
> >
> > test ccount_write
> > rsr a3, ccount
> > rsr a4, ccount
> > sub a4, a4, a3 ; usually 1, but sometimes 2 because of rounding
> > movia2, 0x12345678
> > wsr a2, ccount
> > esync
> > rsr a3, ccount
> > sub a3, a3, a2 ; usually 3 (esync + yield + rsr), but sometimes 4 
> > because of
> rounding
> > sllia4, a4, 2  ; 4 or 8
> > assert  ltu, a3, a4 ; (3 or 4) < (4 or 8) ?
> > test_end
> >
> > Therefore in some cases we get a4=4 and a3=4 that forces the test to fail.

Pavel Dovgalyuk

Re: [Qemu-devel] regression in timer code?

[Max Filippov]

On Wed, Mar 14, 2018 at 2:07 AM, Pavel Dovgalyuk  wrote:
>> From: Max Filippov [mailto:jcmvb...@gmail.com]
>> the commit b39e3f34c9de7ead6a11a74aa2de78baf41d81a7
>> ("icount: fixed saving/restoring of icount warp timers") has changed
>> something that made timers test for target/xtensa unstable.
>> Specifically ccount_write case in the tests/tcg/xtensa/test_timer.S
>> now fails for me about half of the times it is run. Given that it is run
>> under -icount I guess this is a bug. Could you please take a look?
>>
>> The minimal test case is available here:
>>   http://jcmvbkbc.spb.ru/~dumb/tmp/201803131306/test_timer.tst
>> It is run as
>>   qemu-system-xtensa -M sim -cpu dc232b -nographic -semihosting
>> -icount 7  -kernel ./test_timer.tst
>
> I investigated your test and concluded the following.
> First, update_ccount is inaccurate opration because of the division
> with the remainder:
> env->sregs[CCOUNT] = env->ccount_base +
> (uint32_t)((now - env->time_base) *
>env->config->clock_freq_khz / 100);
>
> Therefore, the following sequence in the test may give different result 
> depending
> of the actual value of "now" variable.

But the expression above depends on the difference between the now
and env->time_base, both these values are read from
 qemu_clock_get_ns(QEMU_CLOCK_VIRTUAL) and, most importantly,
the test is 100% deterministic, i.e. it runs under -icount and there's no
external factors involved, no waiting for anything, not even interrupts.
Thus the difference must be constant, i.e. I must see consistent results.
Am I wrong somewhere?

> rsr a3, ccount
> rsr a4, ccount
> sub a4, a4, a3
>
> Consider the code:
>
> test ccount_write
> rsr a3, ccount
> rsr a4, ccount
> sub a4, a4, a3 ; usually 1, but sometimes 2 because of rounding
> movia2, 0x12345678
> wsr a2, ccount
> esync
> rsr a3, ccount
> sub a3, a3, a2 ; usually 3 (esync + yield + rsr), but sometimes 4 
> because of rounding
> sllia4, a4, 2  ; 4 or 8
> assert  ltu, a3, a4 ; (3 or 4) < (4 or 8) ?
> test_end
>
> Therefore in some cases we get a4=4 and a3=4 that forces the test to fail.

-- 
Thanks.
-- Max

Re: [Qemu-devel] regression in timer code?

[Pavel Dovgalyuk]

> From: Max Filippov [mailto:jcmvb...@gmail.com]
> the commit b39e3f34c9de7ead6a11a74aa2de78baf41d81a7
> ("icount: fixed saving/restoring of icount warp timers") has changed
> something that made timers test for target/xtensa unstable.
> Specifically ccount_write case in the tests/tcg/xtensa/test_timer.S
> now fails for me about half of the times it is run. Given that it is run
> under -icount I guess this is a bug. Could you please take a look?
> 
> The minimal test case is available here:
>   http://jcmvbkbc.spb.ru/~dumb/tmp/201803131306/test_timer.tst
> It is run as
>   qemu-system-xtensa -M sim -cpu dc232b -nographic -semihosting
> -icount 7  -kernel ./test_timer.tst

I investigated your test and concluded the following.
First, update_ccount is inaccurate opration because of the division
with the remainder:
env->sregs[CCOUNT] = env->ccount_base +
(uint32_t)((now - env->time_base) *
   env->config->clock_freq_khz / 100);

Therefore, the following sequence in the test may give different result 
depending
of the actual value of "now" variable.
rsr a3, ccount
rsr a4, ccount
sub a4, a4, a3

Consider the code:

test ccount_write
rsr a3, ccount
rsr a4, ccount
sub a4, a4, a3 ; usually 1, but sometimes 2 because of rounding
movia2, 0x12345678
wsr a2, ccount
esync
rsr a3, ccount
sub a3, a3, a2 ; usually 3 (esync + yield + rsr), but sometimes 4 
because of rounding
sllia4, a4, 2  ; 4 or 8
assert  ltu, a3, a4 ; (3 or 4) < (4 or 8) ?
test_end

Therefore in some cases we get a4=4 and a3=4 that forces the test to fail.

Pavel Dovgalyuk

[Qemu-devel] regression in timer code?

[Max Filippov]

Hi Pavel,

the commit b39e3f34c9de7ead6a11a74aa2de78baf41d81a7
("icount: fixed saving/restoring of icount warp timers") has changed
something that made timers test for target/xtensa unstable.
Specifically ccount_write case in the tests/tcg/xtensa/test_timer.S
now fails for me about half of the times it is run. Given that it is run
under -icount I guess this is a bug. Could you please take a look?

The minimal test case is available here:
  http://jcmvbkbc.spb.ru/~dumb/tmp/201803131306/test_timer.tst
It is run as
  qemu-system-xtensa -M sim -cpu dc232b -nographic -semihosting
-icount 7  -kernel ./test_timer.tst

-- 
Thanks.
-- Max