[igt-dev] [PATCH i-g-t v4 2/2] tests/i915/perf_pmu: Add second store dword for looping

[Zbigniew Kempczyński]

On Thu, Jul 21, 2022 at 10:53:22AM +0200, Kamil Konieczny wrote:
> On 2022-07-21 at 06:31:26 +0200, Zbigniew Kempczyński wrote:
> > On Broadwell/Braswell we observe semaphore wait isn't starting sometimes.
> > It's hard to say what's the main reason of this behavior - it happens
> > rare (each 2-3 months). To find out is this delayed write lets add
> > additional store dword for loop condition. Add also some assertions
> > to catch unexpected sw/hw behavior.
> > 
> > References: https://gitlab.freedesktop.org/drm/intel/-/issues/2383
> > 
> > Signed-off-by: Zbigniew Kempczyński <zbigniew.kempczynski at intel.com>
> > ---
> 
> Reviewed-by: Kamil Konieczny <kamil.konieczny at linux.intel.com>

Thanks, anyway we reproduced failure on BDW so it seems there's
write-after-read issue. So I'm not going to merge the series and propose
new one.

--
Zbigniew

> 
> > 
> > v2: Add timeout to break the loop
> > v3: Use debug instead warn and remove early assert (Kamil)
> > ---
> >  tests/i915/perf_pmu.c | 42 +++++++++++++++++++++++++++++++++---------
> >  1 file changed, 33 insertions(+), 9 deletions(-)
> > 
> > diff --git a/tests/i915/perf_pmu.c b/tests/i915/perf_pmu.c
> > index 39e9fc5fef..eae69aae24 100644
> > --- a/tests/i915/perf_pmu.c
> > +++ b/tests/i915/perf_pmu.c
> > @@ -812,6 +812,12 @@ create_sema(int gem_fd, uint64_t ahnd,
> >  		0,
> >  		1,
> >  
> > +		/* Separate write for loop */
> > +		MI_STORE_DWORD_IMM,
> > +		0,
> > +		0,
> > +		2,
> > +
> >  		/* Wait until the semaphore value is set to 0 [by caller] */
> >  		MI_SEMAPHORE_WAIT | MI_SEMAPHORE_POLL | MI_SEMAPHORE_SAD_NEQ_SDD,
> >  		1,
> > @@ -827,17 +833,22 @@ create_sema(int gem_fd, uint64_t ahnd,
> >  	handle = gem_create(gem_fd, 4096);
> >  	*poffset = get_offset(ahnd, handle, 4096, 0);
> >  
> > -	memset(reloc, 0, 2 * sizeof(*reloc));
> > +	memset(reloc, 0, 3 * sizeof(*reloc));
> >  	reloc[0].target_handle = handle;
> >  	reloc[0].offset = 64 + 1 * sizeof(uint32_t);
> >  	reloc[1].target_handle = handle;
> > -	reloc[1].offset = 64 + 6 * sizeof(uint32_t);
> > +	reloc[1].offset = 64 + 5 * sizeof(uint32_t);
> > +	reloc[1].delta = 4;
> > +	reloc[2].target_handle = handle;
> > +	reloc[2].offset = 64 + 10 * sizeof(uint32_t);
> >  
> >  	if (ahnd) {
> >  		cs[1] = *poffset;
> >  		cs[2] = *poffset >> 32;
> > -		cs[6] = *poffset;
> > -		cs[7] = *poffset >> 32;
> > +		cs[5] = *poffset + 4;
> > +		cs[6] = (*poffset + 4) >> 32;
> > +		cs[10] = *poffset;
> > +		cs[11] = *poffset >> 32;
> >  	}
> >  
> >  	gem_write(gem_fd, handle, 64, cs, sizeof(cs));
> > @@ -856,10 +867,10 @@ __sema_busy(int gem_fd, uint64_t ahnd, int pmu, const intel_ctx_t *ctx,
> >  	};
> >  	uint64_t total, sema, busy;
> >  	uint64_t start[2], val[2];
> > -	struct drm_i915_gem_relocation_entry reloc[2];
> > +	struct drm_i915_gem_relocation_entry reloc[3];
> >  	struct drm_i915_gem_exec_object2 obj = {
> >  		.handle = create_sema(gem_fd, ahnd, reloc, &obj.offset),
> > -		.relocation_count = !ahnd ? 2 : 0,
> > +		.relocation_count = !ahnd ? 3 : 0,
> >  		.relocs_ptr = to_user_pointer(reloc),
> >  		.flags = !ahnd ? 0 : EXEC_OBJECT_PINNED,
> >  	};
> > @@ -872,19 +883,32 @@ __sema_busy(int gem_fd, uint64_t ahnd, int pmu, const intel_ctx_t *ctx,
> >  	};
> >  	igt_spin_t *spin;
> >  	uint32_t *map;
> > +	struct timespec tv = {};
> > +	int timeout = 3;
> >  
> >  	/* Time spent being busy includes time waiting on semaphores */
> >  	igt_assert(busy_pct >= sema_pct);
> >  
> >  	gem_quiescent_gpu(gem_fd);
> >  
> > -	map = gem_mmap__device_coherent(gem_fd, obj.handle, 0, 4096, PROT_WRITE);
> > +	map = gem_mmap__device_coherent(gem_fd, obj.handle, 0, 4096, PROT_READ | PROT_WRITE);
> >  	gem_execbuf(gem_fd, &eb);
> > +	igt_debug("[1] bo_busy = %d, map[0] = %u, map[1] = %u\n",
> > +		  gem_bo_busy(gem_fd, obj.handle), map[0], map[1]);
> >  	spin = igt_spin_new(gem_fd, .ahnd = ahnd, .ctx = ctx, .engine = e->flags);
> >  
> > -	/* Wait until the batch is executed and the semaphore is busy-waiting */
> > -	while (!READ_ONCE(*map) && gem_bo_busy(gem_fd, obj.handle))
> > +	/*
> > +	 * Wait until the batch is executed and the semaphore is busy-waiting.
> > +	 * Also stop on timeout.
> > +	 */
> > +	igt_nsec_elapsed(&tv);
> > +	while (READ_ONCE(map[1]) != 2 && gem_bo_busy(gem_fd, obj.handle) &&
> > +	       igt_seconds_elapsed(&tv) < timeout)
> >  		;
> > +	igt_debug("[2] bo_busy = %d, map[0] = %u, map[1] = %u, timeout: [%u/%u]\n",
> > +		  gem_bo_busy(gem_fd, obj.handle), map[0], map[1],
> > +		  igt_seconds_elapsed(&tv), timeout);
> > +	igt_assert(map[0] == 1);
> >  	igt_assert(gem_bo_busy(gem_fd, obj.handle));
> >  	gem_close(gem_fd, obj.handle);
> >  
> > -- 
> > 2.34.1
> >