On Wed, Aug 11, 2021 at 7:37 PM <abhinavk@xxxxxxxxxxxxxx> wrote:
>
> On 2021-08-11 16:28, Rob Clark wrote:
> > On Wed, Aug 11, 2021 at 4:11 PM <abhinavk@xxxxxxxxxxxxxx> wrote:
> >>
> >> On 2021-08-11 11:43, Rob Clark wrote:
> >> > On Wed, Aug 11, 2021 at 11:12 AM Mark Yacoub <markyacoub@xxxxxxxxxxxx>
> >> > wrote:
> >> >>
> >> >> From: Mark Yacoub <markyacoub@xxxxxxxxxx>
> >> >>
> >> >> [why]
> >> >> Reading frame count register used to get the vblank counter, which
> >> >> calls
> >> >> dpu_encoder_phys to get the frame count. Even when it's disabled, the
> >> >> vblank counter (through frame count) should return a valid value for
> >> >> the
> >> >> count. An invalid value of 0, when compared to vblank->last (in
> >> >> drm_vblank.c::drm_update_vblank_count()) returns an invalid number
> >> >> that
> >> >> throws off the vblank counter for the lifetime of the process.
> >> >>
> >> >> Rationale:
> >> >> In drm_vblank.c::drm_update_vblank_count(), the new diff is calculated
> >> >> through:
> >> >> diff = (cur_vblank - vblank->last) & max_vblank_count;
> >> >> cur_vblank comes from: cur_vblank = __get_vblank_counter(dev, pipe);
> >> >> When the value is 0, diff results in a negative number (a very large
> >> >> number as it's unsigned), which inflates the vblank count when the
> >> >> diff
> >> >> is added to the current vblank->count.
> >> >>
> >> >> [How]
> >> >> Read frame_count register whether interface timing engine is enabled
> >> >> or
> >> >> not.
> >> >>
> >> >> Fixes: IGT:kms_flip::modeset-vs-vblank-race-interruptible
> >> >> Tested on ChromeOS Trogdor(msm)
> >> >>
> >> >> Signed-off-by: Mark Yacoub <markyacoub@xxxxxxxxxxxx>
> >> >
> >> > Reviewed-by: Rob Clark <robdclark@xxxxxxxxxxxx>
> >> >
> >> > But I suspect we may have a bit more work for the display-off case..
> >> > or at least I'm not seeing anything obviously doing a pm_runtime_get()
> >> > in this call path.
> >> >
> >> > I'm also not sure if the line/frame-count registers loose state across
> >> > a suspend->resume cycle, it might be that we need to save/restore
> >> > these registers in the suspend/resume path? Abhinav?
> >> >
> >> > BR,
> >> > -R
> >> >
> >> I spent sometime checking this and I dont think we should go ahead
> >> with
> >> this change.
> >> So when the timing engine is off, I believe the reason this works is
> >> that the clocks are still not OFF yet
> >> so this should be returning the last value of the vsync counter before
> >> the timing engine was turned OFF.
> >> If the clocks got turned OFF and there is a power collapse, I expect
> >> the
> >> frame_count and line_count to get reset
> >> to 0.
> >
> > I think if the interface clocks are off, it will be worse.. reading
> > any register will make things go *boom*, won't it?
> >
> > That said, I don't think this patch is making that particular issue
> > worse.
>
> Yes any unclocked access will cause an abort. What I am trying to
> emphasize here
> is that returning the register value after timing engine is off is
> unreliable and should
> not be done. Its working because even though timing engine is off, the
> clocks are not
> yet, so it returns the last value. But we should not rely on it because
> its incorrect
> to check these registers after timing engine off.
>
> >
> >>
> >> I was also looking at the stack in which this error will start
> >> happening. So I believe the sequence is like this
> >> (mark can correct me if wrong):
> >>
> >> drm_crtc_vblank_off(crtc); ---> drm_vblank_disable_and_save ---->
> >> drm_update_vblank_count ----> __get_vblank_counter().
> >>
> >> crtc is disabled after the encoder so this path triggers an incorrect
> >> value because encoder was already disabled (hence timing
> >> engine was too). Clocks were still ON as full suspend hasnt happened
> >> yet.
> >>
> >> To fix this, I think we should do what the downstream drivers did, so
> >> something like this:
> >>
> >> 5471 static u32 dpu_crtc_get_vblank_counter(struct drm_crtc *crtc)
> >> 5472 {
> >> 5473 struct drm_encoder *encoder;
> >> struct dpu_encoder_virt *dpu_enc = NULL;
> >>
> >> dpu_enc = to_dpu_encoder_virt(drm_enc);
> >> 5480
> >> ***********************************************************
> >> 5485 return dpu_encoder_get_frame_count(encoder);
> >> ************************************************************
I'm not quite following what's happening here, this doesn't look much
like the function i see on cros.
> >>
> >> this just returns phys->vsync_cnt (which is just an atomic counter
> >> which
> >> doesnt reset during disable)
> >> So in other words instead of relying on the hw register value which
> >> can
> >> be unpredictable when the timing engine is off,
> >> use a sw counter
> >
> > I don't think that a sw counter will do the job, unless we never
> > disable the vblank irq (or I am misunderstanding you).. the frame
> > counter is expected to keep incrementing regardless of whether vblank
> > is enabled or not.
> >
> > But it does sound like on suspend we need to store the current frame
> > count, and add that offset later when asked for the current frame
> > counter.
> >
> > BR,
> > -R
> the sw counter which i am referring to is already present in
> dpu_encoder.c
> its never reset during disable and should do the job.
>
> Yes, in principle yes, we need to store the current frame count before
> suspend.
> Thats what the phys->vsync_cnt will do and wont get reset.
So i ran the code for both values, when it's on, i see them both
having positive integers but they're not equal in any way. vsync count
seems to be off
```
[ 83.627347] [drm:drm_mode_object_put] OBJ ID: 58 (1)
[ 83.643559] get_frame_count->4887 3962<-vsync_cnt
[ 83.643595] msm ae00000.mdss:
[drm:drm_crtc_vblank_helper_get_vblank_timestamp_internal] crtc 0 : v
p(0,-33)@ 83.606630 -> 83.607121 [e 2 us, 0 rep]
[ 83.643663] get_frame_count->4887 3962<-vsync_cnt
[ 83.643677] msm ae00000.mdss: [drm:drm_update_vblank_count]
updating vblank count on crtc 0: current=38654714967, diff=1, hw=4887
hw_last=4886
[ 83.643722] msm ae00000.mdss: [drm:vblank_disable_fn] disabling
vblank on crtc 0
[ 83.643750] get_frame_count->4887 3962<-vsync_cnt
[ 83.643763] msm ae00000.mdss:
[drm:drm_crtc_vblank_helper_get_vblank_timestamp_internal] crtc 0 : v
p(0,-22)@ 83.606803 -> 83.607131 [e 1 us, 0 rep]
[ 83.643811] get_frame_count->4887 3962<-vsync_cnt
[ 83.643823] msm ae00000.mdss: [drm:drm_update_vblank_count]
updating vblank count on crtc 0: current=38654714968, diff=0, hw=4887
hw_last=4887
```
I see vsync always having values though (at enabling and disabling)
```
[ 82.887961] [drm:dpu_crtc_disable] crtc51
[ 82.887977] msm ae00000.mdss: [drm:drm_crtc_vblank_off] crtc 0,
vblank enabled 1, inmodeset 0
[ 82.887998] get_frame_count->0 3939<-vsync_cnt
[ 82.888008] msm ae00000.mdss:
[drm:drm_crtc_vblank_helper_get_vblank_timestamp_internal] crtc 0 : v
p(0,-38)@ 82.851427 -> 82.851992 [e 1 us, 0 rep]
[ 82.888038] get_frame_count->0 3939<-vsync_cnt
```
should we create a s->frame_count_cached and save the value of
frame_count whenever it's read when s->is_en?
>
> >
> >> 5486 }
> >> 5487
> >> 5488 return 0;
> >> 5489 }
> >>
> >>
> >> >> ---
> >> >> drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.c | 9 ++-------
> >> >> drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.h | 2 +-
> >> >> 2 files changed, 3 insertions(+), 8 deletions(-)
> >> >>
> >> >> diff --git a/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.c
> >> >> b/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.c
> >> >> index 116e2b5b1a90f..c436d901629f3 100644
> >> >> --- a/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.c
> >> >> +++ b/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.c
> >> >> @@ -266,13 +266,8 @@ static void dpu_hw_intf_get_status(
> >> >>
> >> >> s->is_en = DPU_REG_READ(c, INTF_TIMING_ENGINE_EN);
> >> >> s->is_prog_fetch_en = !!(DPU_REG_READ(c, INTF_CONFIG) &
> >> >> BIT(31));
> >> >> - if (s->is_en) {
> >> >> - s->frame_count = DPU_REG_READ(c, INTF_FRAME_COUNT);
> >> >> - s->line_count = DPU_REG_READ(c, INTF_LINE_COUNT);
> >> >> - } else {
> >> >> - s->line_count = 0;
> >> >> - s->frame_count = 0;
> >> >> - }
> >> >> + s->frame_count = DPU_REG_READ(c, INTF_FRAME_COUNT);
> >> >> + s->line_count = DPU_REG_READ(c, INTF_LINE_COUNT);
> >> >> }
> >> >>
> >> >> static u32 dpu_hw_intf_get_line_count(struct dpu_hw_intf *intf)
> >> >> diff --git a/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.h
> >> >> b/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.h
> >> >> index 3568be80dab51..877ff48bfef04 100644
> >> >> --- a/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.h
> >> >> +++ b/drivers/gpu/drm/msm/disp/dpu1/dpu_hw_intf.h
> >> >> @@ -41,7 +41,7 @@ struct intf_prog_fetch {
> >> >> struct intf_status {
> >> >> u8 is_en; /* interface timing engine is enabled
> >> >> or not */
> >> >> u8 is_prog_fetch_en; /* interface prog fetch counter is
> >> >> enabled or not */
> >> >> - u32 frame_count; /* frame count since timing engine
> >> >> enabled */
> >> >> + u32 frame_count; /* frame count since timing engine first
> >> >> enabled */
> >> >> u32 line_count; /* current line count including
> >> >> blanking */
> >> >> };
> >> >>
> >> >> --
> >> >> 2.33.0.rc1.237.g0d66db33f3-goog
> >> >>
