Re: [PATCH v2 26/29] drm/xe: Add SVM debug

["Thomas Hellström" <thomas.hellstrom@linux.intel.com>]

On Tue, 2024-10-15 at 20:25 -0700, Matthew Brost wrote:
> Add some useful SVM debug logging.
> 
> v2:
>  - Upadte logging with latest structure layout
> 
> Signed-off-by: Matthew Brost <matthew.brost@intel.com>
> ---
>  drivers/gpu/drm/xe/xe_pt.c  |   8 +++
>  drivers/gpu/drm/xe/xe_svm.c | 101 +++++++++++++++++++++++++++++++---
> --
>  drivers/gpu/drm/xe/xe_svm.h |   2 +
>  3 files changed, 99 insertions(+), 12 deletions(-)
> 
> diff --git a/drivers/gpu/drm/xe/xe_pt.c b/drivers/gpu/drm/xe/xe_pt.c
> index 687abd1a5e74..75f548ebe2b3 100644
> --- a/drivers/gpu/drm/xe/xe_pt.c
> +++ b/drivers/gpu/drm/xe/xe_pt.c
> @@ -632,6 +632,7 @@ xe_pt_stage_bind(struct xe_tile *tile, struct
> xe_vma *vma,
>  		/* Move this entire thing to xe_svm.c? */
>  		xe_svm_notifier_lock(xe_vma_vm(vma));
>  		if (!xe_svm_range_pages_valid(range)) {
> +			xe_svm_range_debug(range, "BIND PREPARE -
> RETRY");
>  			xe_svm_notifier_unlock(xe_vma_vm(vma));
>  			return -EAGAIN;
>  		}
> @@ -640,6 +641,10 @@ xe_pt_stage_bind(struct xe_tile *tile, struct
> xe_vma *vma,
>  					 range->base.va.end - range-
> >base.va.start,
>  					 &curs);
>  			is_devmem = xe_res_is_vram(&curs);
> +			if (is_devmem)
> +				xe_svm_range_debug(range, "BIND
> PREPARE - DMA VRAM");
> +			else
> +				xe_svm_range_debug(range, "BIND
> PREPARE - DMA");
>  		} else {
>  			xe_assert(xe, false);
>  		}
> @@ -1397,10 +1402,13 @@ static int xe_pt_svm_pre_commit(struct
> xe_migrate_pt_update *pt_update)
>  		if (op->subop == XE_VMA_SUBOP_UNMAP_RANGE)
>  			continue;
>  
> +		xe_svm_range_debug(range, "PRE-COMMIT");
> +
>  		xe_assert(vm->xe, xe_vma_is_system_allocator(op-
> >map_range.vma));
>  		xe_assert(vm->xe, op->subop ==
> XE_VMA_SUBOP_MAP_RANGE);
>  
>  		if (!xe_svm_range_pages_valid(range)) {
> +			xe_svm_range_debug(range, "PRE-COMMIT -
> RETRY");
>  			xe_svm_notifier_unlock(vm);
>  			return -EAGAIN;
>  		}
> diff --git a/drivers/gpu/drm/xe/xe_svm.c
> b/drivers/gpu/drm/xe/xe_svm.c
> index 555bc71ae523..acf2a3750f38 100644
> --- a/drivers/gpu/drm/xe/xe_svm.c
> +++ b/drivers/gpu/drm/xe/xe_svm.c
> @@ -14,6 +14,18 @@
>  #include "xe_vm.h"
>  #include "xe_vm_types.h"
>  
> +static bool xe_svm_range_in_vram(struct xe_svm_range *range)
> +{
> +	/* Not reliable without notifier lock */

lockdep assert?

> +	return range->base.flags.has_devmem_pages;
> +}
> +
> +static bool xe_svm_range_has_vram_binding(struct xe_svm_range
> *range)
> +{
> +	/* Not reliable without notifier lock */

lockdep assert?

> +	return xe_svm_range_in_vram(range) && range->tile_present;
> +}
> +
>  static struct xe_vm *gpusvm_to_vm(struct drm_gpusvm *gpusvm)
>  {
>  	return container_of(gpusvm, struct xe_vm, svm.gpusvm);
> @@ -24,6 +36,23 @@ static struct xe_vm *range_to_vm(struct
> drm_gpusvm_range *r)
>  	return gpusvm_to_vm(r->gpusvm);
>  }
>  
> +#define range_debug(r__,
> operaton__)					\
> +	vm_dbg(&range_to_vm(&(r__)->base)->xe-
> >drm,			\
> +	       "%s: asid=%u, gpusvm=0x%016llx, vram=%d,%d,
> seqno=%lu, " \
> +	       "start=0x%014llx, end=0x%014llx,
> size=%llu",		\
> +	       (operaton__), range_to_vm(&(r__)->base)-
> >usm.asid,	\
> +	       (u64)(r__)-
> >base.gpusvm,					\
> +	       xe_svm_range_in_vram((r__)) ? 1 :
> 0,			\
> +	       xe_svm_range_has_vram_binding((r__)) ? 1 :
> 0,		\
> +	       (r__)-
> >base.notifier_seq,				\
> +	       (r__)->base.va.start, (r__)-
> >base.va.end,		\
> +	       (r__)->base.va.end - (r__)->base.va.start)
> +
> +void xe_svm_range_debug(struct xe_svm_range *range, const char
> *operation)
> +{
> +	range_debug(range, operation);
> +}
> +
>  static void *xe_svm_devm_owner(struct xe_device *xe)
>  {
>  	return xe;
> @@ -61,6 +90,8 @@ xe_svm_garbage_collector_add_range(struct xe_vm
> *vm, struct xe_svm_range *range,
>  {
>  	struct xe_device *xe = vm->xe;
>  
> +	range_debug(range, "GARBAGE COLLECTOR ADD");
> +
>  	drm_gpusvm_range_set_unmapped(&range->base, mmu_range);
>  
>  	spin_lock(&vm->svm.garbage_collector.lock);
> @@ -84,10 +115,14 @@ xe_svm_range_notifier_event_begin(struct xe_vm
> *vm, struct drm_gpusvm_range *r,
>  	u8 tile_mask = 0;
>  	u8 id;
>  
> +	range_debug(range, "NOTIFIER");
> +
>  	/* Skip if already unmapped or if no binding exist */
>  	if (range->base.flags.unmapped || !range->tile_present)
>  		return 0;
>  
> +	range_debug(range, "NOTIFIER - EXECUTE");
> +
>  	/* Adjust invalidation to range boundaries */
>  	if (range->base.va.start < mmu_range->start)
>  		*adj_start = range->base.va.start;
> @@ -139,6 +174,11 @@ static void xe_svm_invalidate(struct drm_gpusvm
> *gpusvm,
>  	if (xe_vm_is_closed(vm))
>  		return;
>  
> +	vm_dbg(&gpusvm_to_vm(gpusvm)->xe->drm,
> +	       "INVALIDATE: asid=%u, gpusvm=0x%016llx, seqno=%lu,
> start=0x%016lx, end=0x%016lx, event=%d",
> +	       vm->usm.asid, (u64)gpusvm, notifier-
> >notifier.invalidate_seq,
> +	       mmu_range->start, mmu_range->end, mmu_range->event);
> +
>  	/* Adjust invalidation to notifier boundaries */
>  	if (adj_start < notifier->interval.start)
>  		adj_start = notifier->interval.start;
> @@ -218,8 +258,12 @@ static int __xe_svm_garbage_collector(struct
> xe_vm *vm,
>  {
>  	struct dma_fence *fence;
>  
> -	if (IS_DGFX(vm->xe) && range->base.flags.partial_unmap)
> +	range_debug(range, "GARBAGE COLLECTOR");
> +
> +	if (IS_DGFX(vm->xe) && range->base.flags.partial_unmap) {
> +		range_debug(range, "GARBAGE COLLECTOT - EVICT");
Typo COLLECTOT

With those fixed,
Reviewed-by: Thomas Hellström <thomas.hellstrom@linux.intel.com>




>  		drm_gpusvm_range_evict(&vm->svm.gpusvm, &range-
> >base);
> +	}
>  
>  	xe_vm_lock(vm, false);
>  	fence = xe_vm_range_unbind(vm, range);
> @@ -350,16 +394,23 @@ static int xe_svm_copy(struct page **pages,
> dma_addr_t *dma_addr,
>  			int incr = (match && last) ? 1 : 0;
>  
>  			if (vram_addr != VRAM_ADDR_INVALID) {
> -				if (sram)
> +				if (sram) {
> +					vm_dbg(&tile->xe->drm,
> +					       "COPY TO SRAM -
> 0x%016llx -> 0x%016llx, NPAGES=%ld",
> +					       vram_addr,
> dma_addr[pos], i - pos + incr);
>  					__fence =
> xe_migrate_from_vram(tile->migrate,
>  								    
>    i - pos + incr,
>  								    
>    vram_addr,
>  								    
>    dma_addr + pos);
> -				else
> +				} else {
> +					vm_dbg(&tile->xe->drm,
> +					       "COPY TO VRAM -
> 0x%016llx -> 0x%016llx, NPAGES=%ld",
> +					       dma_addr[pos],
> vram_addr, i - pos + incr);
>  					__fence =
> xe_migrate_to_vram(tile->migrate,
>  								    
> i - pos + incr,
>  								    
> dma_addr + pos,
>  								    
> vram_addr);
> +				}
>  				if (IS_ERR(__fence)) {
>  					err = PTR_ERR(__fence);
>  					goto err_out;
> @@ -377,14 +428,21 @@ static int xe_svm_copy(struct page **pages,
> dma_addr_t *dma_addr,
>  			}
>  
>  			if (!match && last && dma_addr[i] && spage)
> {
> -				if (sram)
> +				if (sram) {
> +					vm_dbg(&tile->xe->drm,
> +					       "COPY TO SRAM -
> 0x%016llx -> 0x%016llx, NPAGES=%d",
> +					       vram_addr,
> dma_addr[pos], 1);
>  					__fence =
> xe_migrate_from_vram(tile->migrate, 1,
>  								    
>    vram_addr,
>  								    
>    dma_addr + pos);
> -				else
> +				} else {
> +					vm_dbg(&tile->xe->drm,
> +					       "COPY TO VRAM -
> 0x%016llx -> 0x%016llx, NPAGES=%d",
> +					       dma_addr[pos],
> vram_addr, 1);
>  					__fence =
> xe_migrate_to_vram(tile->migrate, 1,
>  								    
> dma_addr + pos,
>  								    
> vram_addr);
> +				}
>  				if (IS_ERR(__fence)) {
>  					err = PTR_ERR(__fence);
>  					goto err_out;
> @@ -554,12 +612,14 @@ static struct xe_bo *xe_svm_alloc_vram(struct
> xe_vm *vm, struct xe_tile *tile,
>  				       const struct drm_gpusvm_ctx
> *ctx)
>  {
>  	struct xe_mem_region *mr = tile_to_mr(tile);
> +	struct drm_buddy *buddy = tile_to_buddy(tile);
>  	struct drm_buddy_block *block;
>  	struct list_head *blocks;
>  	struct xe_bo *bo;
>  	ktime_t end = 0;
>  	int err;
>  
> +	range_debug(range, "ALLOCATE VRAM");
>  retry:
>  	xe_vm_lock(vm, false);
>  	bo = xe_bo_create(tile_to_xe(tile), tile, vm, range-
> >base.va.end -
> @@ -582,8 +642,13 @@ static struct xe_bo *xe_svm_alloc_vram(struct
> xe_vm *vm, struct xe_tile *tile,
>  			       range->base.va.start);
>  
>  	blocks = &to_xe_ttm_vram_mgr_resource(bo->ttm.resource)-
> >blocks;
> -	list_for_each_entry(block, blocks, link)
> +	list_for_each_entry(block, blocks, link) {
> +		vm_dbg(&vm->xe->drm, "ALLOC VRAM: asid=%u,
> gpusvm=0x%016llx, pfn=%llu, npages=%llu",
> +		       vm->usm.asid, (u64)&vm->svm.gpusvm,
> +		       block_offset_to_pfn(mr,
> drm_buddy_block_offset(block)),
> +		       drm_buddy_block_size(buddy, block) >>
> PAGE_SHIFT);
>  		block->private = mr;
> +	}
>  
>  	/*
>  	 * Take ref because as soon as drm_gpusvm_migrate_to_devmem
> succeeds the
> @@ -637,6 +702,8 @@ int xe_svm_handle_pagefault(struct xe_vm *vm,
> struct xe_vma *vma,
>  	if (xe_svm_range_is_valid(range, tile))
>  		return 0;
>  
> +	range_debug(range, "PAGE FAULT");
> +
>  	/* XXX: Add migration policy, for now migrate range once */
>  	if (IS_DGFX(vm->xe) && !range->migrated &&
>  	    range->base.flags.migrate_devmem &&
> @@ -646,25 +713,33 @@ int xe_svm_handle_pagefault(struct xe_vm *vm,
> struct xe_vma *vma,
>  		bo = xe_svm_alloc_vram(vm, tile, range, &ctx);
>  		if (IS_ERR(bo)) {
>  			drm_info(&vm->xe->drm,
> -				 "VRAM allocation failed, falling
> back to retrying, asid=%u, errno %ld\n",
> -				 vm->usm.asid, PTR_ERR(bo));
> +				 "VRAM allocation failed, falling
> back to retrying, asid=%u, gpusvm=0x%016llx, errno %ld\n",
> +				 vm->usm.asid, (u64)&vm->svm.gpusvm,
> +				 PTR_ERR(bo));
>  			bo = NULL;
>  			goto retry;
>  		}
>  	}
>  
> +	range_debug(range, "GET PAGES");
>  	err = drm_gpusvm_range_get_pages(&vm->svm.gpusvm, r, &ctx);
> -	if (err == -EFAULT || err == -EPERM)	/* Corner where CPU
> mappings have change */
>  	if (err == -EOPNOTSUPP || err == -EFAULT || err == -EPERM)
> {	/* Corner where CPU mappings have change */
> -		if (err == -EOPNOTSUPP)
> +		if (err == -EOPNOTSUPP) {
> +			range_debug(range, "PAGE FAULT - EVICT
> PAGES");
>  			drm_gpusvm_range_evict(&vm->svm.gpusvm,
> &range->base);
> +		}
>  		drm_info(&vm->xe->drm,
>  			 "Get pages failed, falling back to
> retrying, asid=%u, gpusvm=0x%016llx, errno %d\n",
>  			 vm->usm.asid, (u64)&vm->svm.gpusvm, err);
> +		range_debug(range, "PAGE FAULT - RETRY PAGES");
>  		goto retry;
>  	}
> -	if (err)
> +	if (err) {
> +		range_debug(range, "PAGE FAULT - FAIL PAGE
> COLLECT");
>  		goto err_out;
> +	}
> +
> +	range_debug(range, "PAGE FAULT - BIND");
>  
>  retry_bind:
>  	drm_exec_init(&exec, 0, 0);
> @@ -680,8 +755,10 @@ int xe_svm_handle_pagefault(struct xe_vm *vm,
> struct xe_vma *vma,
>  		if (IS_ERR(fence)) {
>  			drm_exec_fini(&exec);
>  			err = PTR_ERR(fence);
> -			if (err == -EAGAIN)
> +			if (err == -EAGAIN) {
> +				range_debug(range, "PAGE FAULT -
> RETRY BIND");
>  				goto retry;
> +			}
>  			if (xe_vm_validate_should_retry(&exec, err,
> &end))
>  				goto retry_bind;
>  			goto err_out;
> diff --git a/drivers/gpu/drm/xe/xe_svm.h
> b/drivers/gpu/drm/xe/xe_svm.h
> index 5b9d5ac9ef72..139acee41b42 100644
> --- a/drivers/gpu/drm/xe/xe_svm.h
> +++ b/drivers/gpu/drm/xe/xe_svm.h
> @@ -36,6 +36,8 @@ int xe_svm_handle_pagefault(struct xe_vm *vm,
> struct xe_vma *vma,
>  			    bool atomic);
>  bool xe_svm_has_mapping(struct xe_vm *vm, u64 start, u64 end);
>  
> +void xe_svm_range_debug(struct xe_svm_range *range, const char
> *operation);
> +
>  int xe_svm_bo_evict(struct xe_bo *bo);
>  
>  static inline bool xe_svm_range_pages_valid(struct xe_svm_range
> *range)