Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Mon, 18 Mar 2019 16:36:11 -0300
From:   Rodrigo Siqueira <rodrigosiqueiramelo@gmail.com>
To:     Ville =?utf-8?B?U3lyasOkbMOk?= <ville.syrjala@linux.intel.com>
Cc:     Shayenne Moura <shayenneluzmoura@gmail.com>,
        Haneen Mohammed <hamohammed.sa@gmail.com>,
        David Airlie <airlied@linux.ie>,
        dri-devel <dri-devel@lists.freedesktop.org>,
        Linux Kernel Mailing List <linux-kernel@vger.kernel.org>
Subject: Re: [PATCH] drm/vkms: Solve bug on kms_crc_cursor tests
Message-ID: <20190318193611.gbsnl3un6znujr3w@smtp.gmail.com>
References: <20190228101107.GL2665@phenom.ffwll.local>
 <20190228140341.GG20097@intel.com>
 <CAKkTe8Ei2fbz4L2noLvGWMCsHy1f7sadOV-horjNsGBEHt=q3w@mail.gmail.com>
 <20190301152558.GR20097@intel.com>
 <CAKkTe8HbgkVm1i2xAFT6ecgv2jFjyoqrSEYUpx_40Uj=ogKYPQ@mail.gmail.com>
 <20190301184147.GS20097@intel.com>
 <20190310203505.2needmil76a4rc74@smtp.gmail.com>
 <20190311142710.GY3888@intel.com>
 <20190315115157.6jqvnsddzmvz7jar@smtp.gmail.com>
 <20190315134833.GA3888@intel.com>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
        protocol="application/pgp-signature"; boundary="w5dxbsyiubkhxxav"
Content-Disposition: inline
In-Reply-To: <20190315134833.GA3888@intel.com>
User-Agent: NeoMutt/20180716
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk


--w5dxbsyiubkhxxav
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On 03/15, Ville Syrj=C3=A4l=C3=A4 wrote:
> On Fri, Mar 15, 2019 at 08:51:57AM -0300, Rodrigo Siqueira wrote:
> > On 03/11, Ville Syrj=C3=A4l=C3=A4 wrote:
> > > On Sun, Mar 10, 2019 at 05:35:05PM -0300, Rodrigo Siqueira wrote:
> > > > On 03/01, Ville Syrj=C3=A4l=C3=A4 wrote:
> > > > > On Fri, Mar 01, 2019 at 03:35:35PM -0300, Shayenne Moura wrote:
> > > > > > Em sex, 1 de mar de 2019 =C3=A0s 12:26, Ville Syrj=C3=A4l=C3=A4
> > > > > > <ville.syrjala@linux.intel.com> escreveu:
> > > > > > >
> > > > > > > On Fri, Mar 01, 2019 at 11:55:11AM -0300, Shayenne Moura wrot=
e:
> > > > > > > > Em qui, 28 de fev de 2019 =C3=A0s 11:03, Ville Syrj=C3=A4l=
=C3=A4
> > > > > > > > <ville.syrjala@linux.intel.com> escreveu:
> > > > > > > > >
> > > > > > > > > On Thu, Feb 28, 2019 at 11:11:07AM +0100, Daniel Vetter w=
rote:
> > > > > > > > > > On Mon, Feb 25, 2019 at 11:26:06AM -0300, Shayenne Mour=
a wrote:
> > > > > > > > > > > vkms_crc_work_handle needs the value of the actual fr=
ame to
> > > > > > > > > > > schedule the workqueue that calls periodically the vb=
lank
> > > > > > > > > > > handler and the destroy state functions. However, the=
 frame
> > > > > > > > > > > value returned from vkms_vblank_simulate is updated a=
nd
> > > > > > > > > > > diminished in vblank_get_timestamp because it is not =
in a
> > > > > > > > > > > vblank interrupt, and return an inaccurate value.
> > > > > > > > > > >
> > > > > > > > > > > Solve this getting the actual vblank frame directly f=
rom the
> > > > > > > > > > > vblank->count inside the `struct drm_crtc`, instead o=
f using
> > > > > > > > > > > the `drm_accurate_vblank_count` function.
> > > > > > > > > > >
> > > > > > > > > > > Signed-off-by: Shayenne Moura <shayenneluzmoura@gmail=
=2Ecom>
> > > > > > > > > >
> > > > > > > > > > Sorry for the delay, I'm a bit swamped right now :-/
> > > > > > > > > >
> > > > > > > > > > Debug work you're doing here is really impressive! But =
I have no idea
> > > > > > > > > > what's going on. It doesn't look like it's just paperin=
g over a bug (like
> > > > > > > > > > the in_vblank_irq check we've discussed on irc), but I =
also have no idea
> > > > > > > > > > why it works.
> > > > > > > > > >
> > > > > > > > > > I'll pull in Ville, he understands this better than me.
> > > > > > > > >
> > > > > > > > > It's not entirely clear what we're trying to fix. From wh=
at I can see
> > > > > > > > > the crc work seems to be in no way synchronized with page=
 flips, so
> > > > > > > > > I'm not sure how all this is really supposed to work.
> > > > > > > > >
> > > > > > > >
> > > > > > > > Hi, Ville!
> > > > > > > >
> > > > > > > > Thank you for the review! :)
> > > > > > > >
> > > > > > > > I do not understand well what crc code is doing, but the is=
sue that I found
> > > > > > > > is related to the vblank timestamp and frame count.
> > > > > > > >
> > > > > > > > When vkms handles the crc_cursor it uses the start frame an=
d end frame
> > > > > > > > values to verify if it needs to call the function 'drm_crtc=
_add_crc_entry()'
> > > > > > > > for each frame.
> > > > > > > >
> > > > > > > > However, when getting the frame count, the code is calling =
the function
> > > > > > > > drm_update_vblank_count(dev, pipe, false) and, because of t=
he 'false',
> > > > > > > > subtracting the actual vblank timestamp (consequently, the =
frame count
> > > > > > > > value), causing conflicts.
> > > > > > >
> > > > > > > The in_vblank_irq behavour looks sane to me. What are these c=
onflicts?
> > > > > > >
> > > > > >=20
> > > > > > The entire history was:
> > > > > >  - I sent the patch with bugfix for vblank extra frame. The pat=
ch changed
> > > > > >    our function vkms_get_vblank_timestamp() to look like this:
> > > > > >=20
> > > > > > bool vkms_get_vblank_timestamp(struct drm_device *dev, unsigned=
 int pipe,
> > > > > >                    int *max_error, ktime_t *vblank_time,
> > > > > >                    bool in_vblank_irq)
> > > > > > {
> > > > > >     struct vkms_device *vkmsdev =3D drm_device_to_vkms_device(d=
ev);
> > > > > >     struct vkms_output *output =3D &vkmsdev->output;
> > > > > >=20
> > > > > >     *vblank_time =3D output->vblank_hrtimer.node.expires;
> > > > > >=20
> > > > > > +   if (!in_vblank_irq)
> > > > > > +        *vblank_time -=3D output->period_ns;
> > > > > >=20
> > > > > >     return true;
> > > > > > }
> > > > > >=20
> > > > > >  - This patch solve the issue that I was looking for (extra vbl=
ank
> > > > > > frames on kms_flip).
> > > > > >=20
> > > > > >  - However, kms_cursor_crc tests, which passed before my patch,=
 started to fail.
> > > > > >=20
> > > > > >  - Debugging them, I found that the problem was inside of funct=
ion
> > > > > > `vkms_vblank_simulate()`
> > > > > > when it was handling the crc_enabled (inside  if (state && outp=
ut->crc_enabled))
> > > > > > and inside the function vkms_crc_work_handle() too.
> > > > > >=20
> > > > > >  - Following the steps:
> > > > > > 1. Inside vkms_vblank_simulate() we call drm_crtc_accurate_vbla=
nk_count()
> > > > > > 2. In its turn, drm_crtc_accurate_vblank_count() calls the func=
tion
> > > > > >    drm_update_vblank_count(dev, pipe, false).  /* This false is=
 default */
> > > > > > 3. Finally, the =E2=80=9Cfalse=E2=80=9D used in drm_update_vbla=
nk_count(), will be
> > > > > >   passed to vkms_get_vblank_timestamp() and the condition =E2=
=80=9Cif
> > > > > >   (!in_vblank_irq)=E2=80=9D will be executed multiple times (we=
 don=E2=80=99t want it).
> > > > > >=20
> > > > > >  - Inside vkms_crc, the issue is that the returned frame value =
change for
> > > > > > every call of drm_crtc_accurate_vblank_count() because
> > > > > > in_vblank_irq =3D=3D false.
> > > >=20
> > > > Hi Ville,
> > > > =20
> > > > > OK. So why is it changing? AFAICS it should not change unless the
> > > > > timer was moved forward in between the calls.
> > > >=20
> > > > Yes Ville, you=E2=80=99re right. We have to update it only when the=
 function
> > > > vkms_vblank_simulate() is invoked (timer move forward), and FWIU we=
 do
> > > > it when we call drm_crtc_handle_vblank(). However, the current
> > > > implementation of vkms, has a call to drm_crtc_accurate_vblank_coun=
t()
> > > > inside the vkms_vblank_simulate() which is a problem because it also
> > > > update the vblank value. FWIU, this patch fixes this issue by takin=
g the
> > > > count value in the data struct instead of call
> > > > drm_crtc_accurate_vblank_count() which will avoid the extra update.
> > >=20
> > > But why does that extra update change the vblank count?
> >=20
> > Hi,
> >=20
> > I think that I=E2=80=99m failing to explain the issue and the solution =
in this
> > patch, sorry for that... and I apologize in advance for the lengthy
> > email.
> >=20
> > In this sense, allow me to elaborate the whole history in =E2=80=98chro=
nological
> > sections=E2=80=99:
> >=20
> > 1. About the =E2=80=98fake=E2=80=99 Vblank inside VKMS
> >=20
> > Since VKMS is a virtual driver, we do not have real Vblank, and we
> > simulate it by using hrtimers. I registered the function
> > vkms_vblank_simulate() as a callback inside hrtimer; in this function,
> > we do some stuff that can be summarized in the sequence below:
> >=20
> > I) drm_crtc_handle_vblank()
> > II) Check if crc is enabled or not
> > III) Schedule the next vblank with hrtimer_forward_now()
> >=20
> > 2. Override the default behaviour for get_vblank_timestamp()
> >=20
> > As I told before, everytime that vkms_vblank_simulate() is invoked the
> > function drm_crtc_handle_vblank() will be requested. For us, the
> > important thing about drm_crtc_handle_vblank() is the sequence:
> >=20
> >  a) drm_crtc_handle_vblank()
> >  b) drm_handle_vblank()
> >  c) drm_update_vblank_count()
> >  d) drm_get_last_vbltimestamp()
> >  e) get_vblank_timestamp()
> >=20
> > Since VKMS is a virtual driver, we cannot rely on the default
> > implementation of get_vblank_timestamp(). In this context, we
> > implemented our wrapper named vkms_get_vblank_timestamp(), and we have
> > to return the expires time from hrtimer to the userspace. In my first
> > implementation of this function, I had something like:
> >=20
> > bool vkms_get_vblank_timestamp(struct drm_device *dev, unsigned int pip=
e,
> >                                int *max_error, ktime_t *vblank_time,
> >                                bool in_vblank_irq)
> > {
> > [..]
> >         *vblank_time =3D output->vblank_hrtimer.node.expires;
> >         return true;
> > }
> >=20
> > Around 80% of the kms_flip tests were passing with this code. However,
> > we had some tests that break due to an extra vblank.
> >=20
> > 3. The extra vblank bug
> >=20
> > Shayenne and Daniel figured out that the extra vblank came from the
> > function drm_crtc_arm_vblank_event() invoked inside the
> > vkms_crtc_atomic_flush(). If we take a look inside
> > drm_crtc_arm_vblank_event(), we can find:
> >=20
> > void drm_crtc_arm_vblank_event([..])
> > {
> > [..]
> >        e->sequence =3D drm_crtc_accurate_vblank_count(crtc) + 1;
> > [..]
> > }
> >=20
> > This function increment the sequence by one (there is a detailed
> > explanation about it in the documentation of this function).
> >=20
> > 4. The bug fix
> >=20
> > After inspecting the code, we identified the following sequence when the
> > function drm_crtc_arm_vblank_event() is invoked:
> >=20
> >  a) drm_crtc_arm_vblank_event()
> >  b) drm_crtc_accurate_vblank_count()
> >  c) drm_update_vblank_count(dev, pipe, false)
> >=20
> > Noticed that drm_update_vblank_count() is invoked again, but now with
> > =E2=80=98false=E2=80=99 in the in_vblank_irq because it does not have t=
o report anything
> > for userspace or something like that. With this in mind, remember that
> > drm_update_vblank_count() will call get_vblank_timestamp(); with my
> > first implementation of vkms_get_vblank_timestamp() (see Section 2 for
> > recap) we will update the vblank_time with the wrong information. After
> > understanding all of these details and the meaning of the parameter
> > in_vblank_irq, the following fix was added:
> >=20
> > bool vkms_get_vblank_timestamp([..]) {
> > [..]
> >         if (!in_vblank_irq)
> >                 *vblank_time -=3D output->period_ns;
> > [..]
> > }
> >=20
> > With this validation, we can solve the problem of the extra Vblank added
> > by drm_crtc_arm_vblank_event(). Afterward, all the kms_flip test started
> > to pass.
> >=20
> > 5. The new bug on CRC operation
> >=20
> > As a side effect of the above change, the CRC tests start to failing.
> > The question was, why we break the CRC test with that fix?
> >=20
> > We start hunting the problem, and the first thing to look is the
> > function vkms_vblank_simulate(). Inside this function, we have this
> > code:
> >=20
> > vkms_vblank_simulate([..]) {
> > [..]
> >         if (state && output->crc_enabled) {
> >                 u64 frame =3D drm_crtc_accurate_vblank_count(crtc);
> >                 [..]
> >         }
> >=20
> > The output->crc_enabled is a module parameter that enables CRC
> > computation which is required for CRC tests, but not for kms_flip.
> > Additionally, notice that we save the value of the current frame because
> > it is necessary to use it on vkms_crc_work_handle(). The only thing that
> > we need to know about vkms_crc_work_handle() is the fact we call
> > drm_crtc_add_crc_entry() which requires the frame number, and we also
> > use it to check if the frame was updated or not.
> >=20
> > As I said in Section 2, drm_crtc_accurate_vblank_count() calls
> > drm_update_vblank_count() with false parameter in in_vblank_irq. Due to
> > the last change made at vkms_get_vblank_timestamp(), we broke the CRC
> > code because now we invoke get_vblank_timestamp() multiple times. The
> > consequence of this change is the excessive decrement of the timestamp
> > since the following condition execute multiple time:
> >=20
> > bool vkms_get_vblank_timestamp([..]) {
> >         if (!in_vblank_irq)
> >                 *vblank_time -=3D output->period_ns;
>=20
> The full code is
> *vblank_time =3D output->vblank_hrtimer.node.expires;
> if (!in_vblank_irq)
> 	*vblank_time -=3D output->period_ns;
>=20
> So no matter how many times you call it you should always get the same
> answer (unless the timer was moved forwared in between the calls).

Touch=C3=A9! :)

You're right! Thanks for your patience, I finally understood the problem
and now I will dig into it.

Thanks

> >=20
> > 6. The bug fix (this patch)
> >=20
> > Since we only want the frame number, as I described in Section 5, the
> > fix is quite simple: avoid call drm_crtc_accurate_vblank_count() and
> > just get the frame value from the data structure. In this patch,
> > Shayenne removed the function drm_crtc_accurate_vblank_count() which
> > avoid the extra decrement in the vkms_get_vblank_timestamp(). With this
> > patch, everything started to work well.
> >=20
> > So... In a few words, it is a VKMS problem, not a vblank issue.
> >=20
> > I=E2=80=99m not sure if the solution here is the best one, but I believ=
e that
> > the idea behind it is correct.
> >=20
> > Best Regards
> >=20
> > --=20
> > Rodrigo Siqueira
> > https://siqueira.tech
> > Graduate Student
> > Department of Computer Science
> > University of S=C3=A3o Paulo
>=20
>=20
>=20
> --=20
> Ville Syrj=C3=A4l=C3=A4
> Intel

--=20
Rodrigo Siqueira
https://siqueira.tech
Graduate Student
Department of Computer Science
University of S=C3=A3o Paulo

--w5dxbsyiubkhxxav
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEE4tZ+ii1mjMCMQbfkWJzP/comvP8FAlyP8yoACgkQWJzP/com
vP9nTw//fwzspLHmqI5cI7ZjVdTPUDxWCpNZ4MaFDS5yY74KzKvA89JSjBGE3o3w
DhQFrTtX3civ0esB0dQaVDjxHRJlp6mw6MxJJ4txDVUVAkK3r5gN1tyQ52AmAYoB
Gexqon3OaSsjMcIWBBr4DB4np71eIeAQipI0bwGXeWbuXgCghpFMkdZCeqBSw8tZ
bGs+opou2egQ1KG2xCMfJEBf3pQw/UfLvDLviH6PKs88rTxizP4KQ4Vy8HltZsNK
vsAkzQKnMeOTi/xE7ZxI2c4U9fTp5ZG7wU5pNAUBxP9BZDhptkG0/ELf55BVj2YT
Vnmsw1IdXj+ielgbXGJdcQOw84tUbnhGIh3/Y39W1GFcB1YD8pPNnh8ETHQCvKa8
Lma3BxXh/Z3xmZOg+RG+UYLqDPffeOLik/s1gvRBSk4sZWWHchtgEySRE+eu2DkM
PhqGcAV9NDEik45/Rt/hM8qgmeVpir9QU9Ibd8k7wei3XFJ1D4kuAExpxDoVZOLp
w2WBoAnCcQyXmn59Xidro/IGJU3C2VRyzmNGnsvdDTJfjLzSetCOH9n0g7eV/1Lh
futtWk1p07mTnMp5GtVjHEyHfx+pR8uFXCY29jF4reMuy1et29QquDmWpSaAqUXg
ZT5CfgeoejJrInoeZ4B1hXgxDTINnPMryGw7sw1WQK/wfLmiO0E=
=r2Ee
-----END PGP SIGNATURE-----

--w5dxbsyiubkhxxav--