[Qemu-devel] regression in timer code?

[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

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

[Pavel Dovgalyuk]

> From: Max Filippov [mailto:jcmvbkbc@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 / 1000000);

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
    movi    a2, 0x12345678
    wsr     a2, ccount
    esync
    rsr     a3, ccount
    sub     a3, a3, a2 ; usually 3 (esync + yield + rsr), but sometimes 4 because of rounding
    slli    a4, 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 <dovgaluk@ispras.ru> wrote:
>> From: Max Filippov [mailto:jcmvbkbc@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 / 1000000);
>
> 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
>     movi    a2, 0x12345678
>     wsr     a2, ccount
>     esync
>     rsr     a3, ccount
>     sub     a3, a3, a2 ; usually 3 (esync + yield + rsr), but sometimes 4 because of rounding
>     slli    a4, 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]

> -----Original Message-----
> From: Max Filippov [mailto:jcmvbkbc@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 <dovgaluk@ispras.ru> wrote:
> >> From: Max Filippov [mailto:jcmvbkbc@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 / 1000000);
> >
> > 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
> >     movi    a2, 0x12345678
> >     wsr     a2, ccount
> >     esync
> >     rsr     a3, ccount
> >     sub     a3, a3, a2 ; usually 3 (esync + yield + rsr), but sometimes 4 because of
> rounding
> >     slli    a4, 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:53 AM, Pavel Dovgalyuk <dovgaluk@ispras.ru> 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]

> From: Max Filippov [mailto:jcmvbkbc@gmail.com]
> On Wed, Mar 14, 2018 at 2:53 AM, Pavel Dovgalyuk <dovgaluk@ispras.ru> 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 11:09 PM, Pavel Dovgalyuk <dovgaluk@ispras.ru> wrote:
>> From: Max Filippov [mailto:jcmvbkbc@gmail.com]
>> On Wed, Mar 14, 2018 at 2:53 AM, Pavel Dovgalyuk <dovgaluk@ispras.ru> 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