[PATCH 0/3] drm/xe: Fix races on fdinfo

[PATCH 0/3] drm/xe: Fix races on fdinfo

[Lucas De Marchi]

The current reading of engine utilization has same races. This should
fix most of them while also drastically reducing the update rate needed
on "normal apps".

I left tests/xe_drm_fdinfo running on 2 systems and saw no failures
after 100 iterations.

Lucas De Marchi (3):
  drm/xe: Add trace to lrc timestamp update
  drm/xe: Accumulate exec queue timestamp on destroy
  drm/xe: Stop accumulating LRC timestamp on job_free

 drivers/gpu/drm/xe/Makefile        |  1 +
 drivers/gpu/drm/xe/xe_exec_queue.c | 14 ++++++++
 drivers/gpu/drm/xe/xe_guc_submit.c |  2 --
 drivers/gpu/drm/xe/xe_lrc.c        |  3 ++
 drivers/gpu/drm/xe/xe_trace_lrc.c  |  9 ++++++
 drivers/gpu/drm/xe/xe_trace_lrc.h  | 52 ++++++++++++++++++++++++++++++
 6 files changed, 79 insertions(+), 2 deletions(-)
 create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.c
 create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.h

-- 
2.47.0

[PATCH 1/3] drm/xe: Add trace to lrc timestamp update

[Lucas De Marchi]

Help debugging when LRC timestamp is updated for a exec queue.

Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
---
 drivers/gpu/drm/xe/Makefile       |  1 +
 drivers/gpu/drm/xe/xe_lrc.c       |  3 ++
 drivers/gpu/drm/xe/xe_trace_lrc.c |  9 ++++++
 drivers/gpu/drm/xe/xe_trace_lrc.h | 52 +++++++++++++++++++++++++++++++
 4 files changed, 65 insertions(+)
 create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.c
 create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.h

diff --git a/drivers/gpu/drm/xe/Makefile b/drivers/gpu/drm/xe/Makefile
index bc7a04ce69fd..21d69935c336 100644
--- a/drivers/gpu/drm/xe/Makefile
+++ b/drivers/gpu/drm/xe/Makefile
@@ -101,6 +101,7 @@ xe-y += xe_bb.o \
 	xe_trace.o \
 	xe_trace_bo.o \
 	xe_trace_guc.o \
+	xe_trace_lrc.o \
 	xe_ttm_sys_mgr.o \
 	xe_ttm_stolen_mgr.o \
 	xe_ttm_vram_mgr.o \
diff --git a/drivers/gpu/drm/xe/xe_lrc.c b/drivers/gpu/drm/xe/xe_lrc.c
index 4f64c7f4e68d..4b65da77c6e0 100644
--- a/drivers/gpu/drm/xe/xe_lrc.c
+++ b/drivers/gpu/drm/xe/xe_lrc.c
@@ -25,6 +25,7 @@
 #include "xe_map.h"
 #include "xe_memirq.h"
 #include "xe_sriov.h"
+#include "xe_trace_lrc.h"
 #include "xe_vm.h"
 #include "xe_wa.h"
 
@@ -1758,5 +1759,7 @@ u32 xe_lrc_update_timestamp(struct xe_lrc *lrc, u32 *old_ts)
 
 	lrc->ctx_timestamp = xe_lrc_ctx_timestamp(lrc);
 
+	trace_xe_lrc_update_timestamp(lrc, *old_ts);
+
 	return lrc->ctx_timestamp;
 }
diff --git a/drivers/gpu/drm/xe/xe_trace_lrc.c b/drivers/gpu/drm/xe/xe_trace_lrc.c
new file mode 100644
index 000000000000..ab9b7e2970bc
--- /dev/null
+++ b/drivers/gpu/drm/xe/xe_trace_lrc.c
@@ -0,0 +1,9 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * Copyright © 2024 Intel Corporation
+ */
+
+#ifndef __CHECKER__
+#define CREATE_TRACE_POINTS
+#include "xe_trace_lrc.h"
+#endif
diff --git a/drivers/gpu/drm/xe/xe_trace_lrc.h b/drivers/gpu/drm/xe/xe_trace_lrc.h
new file mode 100644
index 000000000000..5c669a0b2180
--- /dev/null
+++ b/drivers/gpu/drm/xe/xe_trace_lrc.h
@@ -0,0 +1,52 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright © 2024 Intel Corporation
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM xe
+
+#if !defined(_XE_TRACE_LRC_H_) || defined(TRACE_HEADER_MULTI_READ)
+#define _XE_TRACE_LRC_H_
+
+#include <linux/tracepoint.h>
+#include <linux/types.h>
+
+#include "xe_gt_types.h"
+#include "xe_lrc.h"
+#include "xe_lrc_types.h"
+
+#define __dev_name_lrc(lrc)	dev_name(gt_to_xe((lrc)->fence_ctx.gt)->drm.dev)
+
+TRACE_EVENT(xe_lrc_update_timestamp,
+	    TP_PROTO(struct xe_lrc *lrc, uint32_t old),
+	    TP_ARGS(lrc, old),
+	    TP_STRUCT__entry(
+		     __field(struct xe_lrc *, lrc)
+		     __field(u32, old)
+		     __field(u32, new)
+		     __string(name, lrc->fence_ctx.name)
+		     __string(device_id, __dev_name_lrc(lrc))
+	    ),
+
+	    TP_fast_assign(
+		   __entry->lrc	= lrc;
+		   __entry->old = old;
+		   __entry->new = lrc->ctx_timestamp;
+		   __assign_str(name);
+		   __assign_str(device_id);
+		   ),
+	    TP_printk("lrc=:%p lrc->name=%s old=%u new=%u device_id:%s",
+		      __entry->lrc, __get_str(name),
+		      __entry->old, __entry->new,
+		      __get_str(device_id))
+);
+
+#endif
+
+/* This part must be outside protection */
+#undef TRACE_INCLUDE_PATH
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/xe
+#define TRACE_INCLUDE_FILE xe_trace_lrc
+#include <trace/define_trace.h>
-- 
2.47.0

Re: [PATCH 1/3] drm/xe: Add trace to lrc timestamp update

[Nirmoy Das]

On 10/26/2024 8:26 AM, Lucas De Marchi wrote:
> Help debugging when LRC timestamp is updated for a exec queue.
>
> Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>


Reviewed-by: Nirmoy Das <nirmoy.das@intel.com>

> ---
>  drivers/gpu/drm/xe/Makefile       |  1 +
>  drivers/gpu/drm/xe/xe_lrc.c       |  3 ++
>  drivers/gpu/drm/xe/xe_trace_lrc.c |  9 ++++++
>  drivers/gpu/drm/xe/xe_trace_lrc.h | 52 +++++++++++++++++++++++++++++++
>  4 files changed, 65 insertions(+)
>  create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.c
>  create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.h
>
> diff --git a/drivers/gpu/drm/xe/Makefile b/drivers/gpu/drm/xe/Makefile
> index bc7a04ce69fd..21d69935c336 100644
> --- a/drivers/gpu/drm/xe/Makefile
> +++ b/drivers/gpu/drm/xe/Makefile
> @@ -101,6 +101,7 @@ xe-y += xe_bb.o \
>  	xe_trace.o \
>  	xe_trace_bo.o \
>  	xe_trace_guc.o \
> +	xe_trace_lrc.o \
>  	xe_ttm_sys_mgr.o \
>  	xe_ttm_stolen_mgr.o \
>  	xe_ttm_vram_mgr.o \
> diff --git a/drivers/gpu/drm/xe/xe_lrc.c b/drivers/gpu/drm/xe/xe_lrc.c
> index 4f64c7f4e68d..4b65da77c6e0 100644
> --- a/drivers/gpu/drm/xe/xe_lrc.c
> +++ b/drivers/gpu/drm/xe/xe_lrc.c
> @@ -25,6 +25,7 @@
>  #include "xe_map.h"
>  #include "xe_memirq.h"
>  #include "xe_sriov.h"
> +#include "xe_trace_lrc.h"
>  #include "xe_vm.h"
>  #include "xe_wa.h"
>  
> @@ -1758,5 +1759,7 @@ u32 xe_lrc_update_timestamp(struct xe_lrc *lrc, u32 *old_ts)
>  
>  	lrc->ctx_timestamp = xe_lrc_ctx_timestamp(lrc);
>  
> +	trace_xe_lrc_update_timestamp(lrc, *old_ts);
> +
>  	return lrc->ctx_timestamp;
>  }
> diff --git a/drivers/gpu/drm/xe/xe_trace_lrc.c b/drivers/gpu/drm/xe/xe_trace_lrc.c
> new file mode 100644
> index 000000000000..ab9b7e2970bc
> --- /dev/null
> +++ b/drivers/gpu/drm/xe/xe_trace_lrc.c
> @@ -0,0 +1,9 @@
> +// SPDX-License-Identifier: GPL-2.0-only
> +/*
> + * Copyright © 2024 Intel Corporation
> + */
> +
> +#ifndef __CHECKER__
> +#define CREATE_TRACE_POINTS
> +#include "xe_trace_lrc.h"
> +#endif
> diff --git a/drivers/gpu/drm/xe/xe_trace_lrc.h b/drivers/gpu/drm/xe/xe_trace_lrc.h
> new file mode 100644
> index 000000000000..5c669a0b2180
> --- /dev/null
> +++ b/drivers/gpu/drm/xe/xe_trace_lrc.h
> @@ -0,0 +1,52 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Copyright © 2024 Intel Corporation
> + */
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM xe
> +
> +#if !defined(_XE_TRACE_LRC_H_) || defined(TRACE_HEADER_MULTI_READ)
> +#define _XE_TRACE_LRC_H_
> +
> +#include <linux/tracepoint.h>
> +#include <linux/types.h>
> +
> +#include "xe_gt_types.h"
> +#include "xe_lrc.h"
> +#include "xe_lrc_types.h"
> +
> +#define __dev_name_lrc(lrc)	dev_name(gt_to_xe((lrc)->fence_ctx.gt)->drm.dev)
> +
> +TRACE_EVENT(xe_lrc_update_timestamp,
> +	    TP_PROTO(struct xe_lrc *lrc, uint32_t old),
> +	    TP_ARGS(lrc, old),
> +	    TP_STRUCT__entry(
> +		     __field(struct xe_lrc *, lrc)
> +		     __field(u32, old)
> +		     __field(u32, new)
> +		     __string(name, lrc->fence_ctx.name)
> +		     __string(device_id, __dev_name_lrc(lrc))
> +	    ),
> +
> +	    TP_fast_assign(
> +		   __entry->lrc	= lrc;
> +		   __entry->old = old;
> +		   __entry->new = lrc->ctx_timestamp;
> +		   __assign_str(name);
> +		   __assign_str(device_id);
> +		   ),
> +	    TP_printk("lrc=:%p lrc->name=%s old=%u new=%u device_id:%s",
> +		      __entry->lrc, __get_str(name),
> +		      __entry->old, __entry->new,
> +		      __get_str(device_id))
> +);
> +
> +#endif
> +
> +/* This part must be outside protection */
> +#undef TRACE_INCLUDE_PATH
> +#undef TRACE_INCLUDE_FILE
> +#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/xe
> +#define TRACE_INCLUDE_FILE xe_trace_lrc
> +#include <trace/define_trace.h>

[PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Lucas De Marchi]

When the exec queue is destroyed, there's a race between a query to the
fdinfo and the exec queue value being updated: after the destroy ioctl,
if the fdinfo is queried before a call to guc_exec_queue_free_job(),
the wrong utilization is reported: it's not accumulated on the query
since the queue was removed from the array, and the value wasn't updated
yet by the free_job().

Explicitly accumulate the engine utilization so the right value is
visible after the ioctl return.

Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
---
 drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
index d098d2dd1b2d..b15ca84b2422 100644
--- a/drivers/gpu/drm/xe/xe_exec_queue.c
+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
@@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
 
 	xe_exec_queue_kill(q);
 
+	/*
+	 * After killing and destroying the exec queue, make sure userspace has
+	 * an updated view of the run ticks, regardless if this was the last
+	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
+	 * query to fdinfo after this returns could not account for this load.
+	 */
+	xe_exec_queue_update_run_ticks(q);
+
 	trace_xe_exec_queue_close(q);
 	xe_exec_queue_put(q);
 
-- 
2.47.0

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Nirmoy Das]

On 10/26/2024 8:26 AM, Lucas De Marchi wrote:
> When the exec queue is destroyed, there's a race between a query to the
> fdinfo and the exec queue value being updated: after the destroy ioctl,
> if the fdinfo is queried before a call to guc_exec_queue_free_job(),
> the wrong utilization is reported: it's not accumulated on the query
> since the queue was removed from the array, and the value wasn't updated
> yet by the free_job().
>
> Explicitly accumulate the engine utilization so the right value is
> visible after the ioctl return.
>
> Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
> Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
> Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>

LGTM

Reviewed-by: Nirmoy Das <nirmoy.das@intel.com>

> ---
>  drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
>  1 file changed, 8 insertions(+)
>
> diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
> index d098d2dd1b2d..b15ca84b2422 100644
> --- a/drivers/gpu/drm/xe/xe_exec_queue.c
> +++ b/drivers/gpu/drm/xe/xe_exec_queue.c
> @@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>  
>  	xe_exec_queue_kill(q);
>  
> +	/*
> +	 * After killing and destroying the exec queue, make sure userspace has
> +	 * an updated view of the run ticks, regardless if this was the last
> +	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
> +	 * query to fdinfo after this returns could not account for this load.
> +	 */
> +	xe_exec_queue_update_run_ticks(q);
> +
>  	trace_xe_exec_queue_close(q);
>  	xe_exec_queue_put(q);
>  

[PATCH 3/3] drm/xe: Stop accumulating LRC timestamp on job_free

[Lucas De Marchi]

The exec queue timestamp is only really useful when it's being queried
through the fdinfo. There's no need to update it so often, on every
job_free. Tracing a simple app like vkcube running shows an update
rate of ~ 120Hz.

The update on job_free() is used to cover a gap: if exec
queue is created and destroyed rapidily, before a new query, the
timestamp still needs to be accumulated and accounted on the xef.
Initial implementation in commit 6109f24f87d7 ("drm/xe: Add helper to
accumulate exec queue runtime") couldn't do it on the exec_queue_fini
since the xef could be gone at that point. However since commit
ce8c161cbad4 ("drm/xe: Add ref counting for xe_file") the xef is
refcounted and the exec queue has a reference.

Improve the fix in commit 2149ded63079 ("drm/xe: Fix use after free when
client stats are captured") by reducing the frequency in which the
update is needed.

Fixes: 2149ded63079 ("drm/xe: Fix use after free when client stats are captured")
Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
---
 drivers/gpu/drm/xe/xe_exec_queue.c | 6 ++++++
 drivers/gpu/drm/xe/xe_guc_submit.c | 2 --
 2 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
index b15ca84b2422..bc2fc917e0de 100644
--- a/drivers/gpu/drm/xe/xe_exec_queue.c
+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
@@ -260,8 +260,14 @@ void xe_exec_queue_fini(struct xe_exec_queue *q)
 {
 	int i;
 
+	/*
+	 * Before releasing our ref to lrc and xef, accumulate our run ticks
+	 */
+	xe_exec_queue_update_run_ticks(q);
+
 	for (i = 0; i < q->width; ++i)
 		xe_lrc_put(q->lrc[i]);
+
 	__xe_exec_queue_free(q);
 }
 
diff --git a/drivers/gpu/drm/xe/xe_guc_submit.c b/drivers/gpu/drm/xe/xe_guc_submit.c
index e5d7c767a744..ebe4665d9159 100644
--- a/drivers/gpu/drm/xe/xe_guc_submit.c
+++ b/drivers/gpu/drm/xe/xe_guc_submit.c
@@ -747,8 +747,6 @@ static void guc_exec_queue_free_job(struct drm_sched_job *drm_job)
 {
 	struct xe_sched_job *job = to_xe_sched_job(drm_job);
 
-	xe_exec_queue_update_run_ticks(job->q);
-
 	trace_xe_sched_job_free(job);
 	xe_sched_job_put(job);
 }
-- 
2.47.0

✗ Fi.CI.CHECKPATCH: warning for drm/xe: Fix races on fdinfo

[Patchwork]

== Series Details ==

Series: drm/xe: Fix races on fdinfo
URL   : https://patchwork.freedesktop.org/series/140538/
State : warning

== Summary ==

Error: dim checkpatch failed
be111ababfbe drm/xe: Add trace to lrc timestamp update
-:44: WARNING:FILE_PATH_CHANGES: added, moved or deleted file(s), does MAINTAINERS need updating?
#44: 
new file mode 100644

-:87: CHECK:OPEN_ENDED_LINE: Lines should not end with a '('
#87: FILE: drivers/gpu/drm/xe/xe_trace_lrc.h:24:
+	    TP_STRUCT__entry(

-:95: CHECK:OPEN_ENDED_LINE: Lines should not end with a '('
#95: FILE: drivers/gpu/drm/xe/xe_trace_lrc.h:32:
+	    TP_fast_assign(

-:113: CHECK:SPACING: spaces preferred around that '/' (ctx:VxV)
#113: FILE: drivers/gpu/drm/xe/xe_trace_lrc.h:50:
+#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/xe
                              ^

-:113: CHECK:SPACING: spaces preferred around that '/' (ctx:VxV)
#113: FILE: drivers/gpu/drm/xe/xe_trace_lrc.h:50:
+#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/xe
                                 ^

-:113: CHECK:SPACING: spaces preferred around that '/' (ctx:VxV)
#113: FILE: drivers/gpu/drm/xe/xe_trace_lrc.h:50:
+#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/xe
                                         ^

-:113: CHECK:SPACING: spaces preferred around that '/' (ctx:VxV)
#113: FILE: drivers/gpu/drm/xe/xe_trace_lrc.h:50:
+#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/xe
                                             ^

-:113: CHECK:SPACING: spaces preferred around that '/' (ctx:VxV)
#113: FILE: drivers/gpu/drm/xe/xe_trace_lrc.h:50:
+#define TRACE_INCLUDE_PATH ../../drivers/gpu/drm/xe
                                                 ^

total: 0 errors, 1 warnings, 7 checks, 82 lines checked
d88c0ee83457 drm/xe: Accumulate exec queue timestamp on destroy
8a635cead973 drm/xe: Stop accumulating LRC timestamp on job_free

✗ Fi.CI.SPARSE: warning for drm/xe: Fix races on fdinfo

[Patchwork]

== Series Details ==

Series: drm/xe: Fix races on fdinfo
URL   : https://patchwork.freedesktop.org/series/140538/
State : warning

== Summary ==

Error: dim sparse failed
Sparse version: v0.6.2
Fast mode used, each commit won't be checked separately.

✓ Fi.CI.BAT: success for drm/xe: Fix races on fdinfo

[Patchwork]

[-- Attachment #1: Type: text/plain, Size: 3381 bytes --]

== Series Details ==

Series: drm/xe: Fix races on fdinfo
URL   : https://patchwork.freedesktop.org/series/140538/
State : success

== Summary ==

CI Bug Log - changes from CI_DRM_15602 -> Patchwork_140538v1
====================================================

Summary
-------

  **SUCCESS**

  No regressions found.

  External URL: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/index.html

Participating hosts (47 -> 46)
------------------------------

  Missing    (1): fi-snb-2520m 

Known issues
------------

  Here are the changes found in Patchwork_140538v1 that come from known issues:

### IGT changes ###

#### Issues hit ####

  * igt@i915_selftest@live:
    - bat-mtlp-8:         [PASS][1] -> [ABORT][2] ([i915#12133] / [i915#12216])
   [1]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_15602/bat-mtlp-8/igt@i915_selftest@live.html
   [2]: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/bat-mtlp-8/igt@i915_selftest@live.html
    - bat-atsm-1:         [PASS][3] -> [ABORT][4] ([i915#12133])
   [3]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_15602/bat-atsm-1/igt@i915_selftest@live.html
   [4]: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/bat-atsm-1/igt@i915_selftest@live.html

  * igt@i915_selftest@live@guc_multi_lrc:
    - bat-atsm-1:         [PASS][5] -> [ABORT][6] ([i915#12305])
   [5]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_15602/bat-atsm-1/igt@i915_selftest@live@guc_multi_lrc.html
   [6]: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/bat-atsm-1/igt@i915_selftest@live@guc_multi_lrc.html

  * igt@i915_selftest@live@workarounds:
    - bat-mtlp-8:         [PASS][7] -> [ABORT][8] ([i915#12216])
   [7]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_15602/bat-mtlp-8/igt@i915_selftest@live@workarounds.html
   [8]: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/bat-mtlp-8/igt@i915_selftest@live@workarounds.html

  
#### Possible fixes ####

  * igt@i915_selftest@live:
    - bat-dg2-8:          [ABORT][9] ([i915#12133]) -> [PASS][10]
   [9]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_15602/bat-dg2-8/igt@i915_selftest@live.html
   [10]: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/bat-dg2-8/igt@i915_selftest@live.html

  * igt@i915_selftest@live@guc_multi_lrc:
    - bat-dg2-8:          [ABORT][11] ([i915#12133] / [i915#12305]) -> [PASS][12]
   [11]: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_15602/bat-dg2-8/igt@i915_selftest@live@guc_multi_lrc.html
   [12]: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/bat-dg2-8/igt@i915_selftest@live@guc_multi_lrc.html

  
  [i915#12133]: https://gitlab.freedesktop.org/drm/i915/kernel/-/issues/12133
  [i915#12216]: https://gitlab.freedesktop.org/drm/i915/kernel/-/issues/12216
  [i915#12305]: https://gitlab.freedesktop.org/drm/i915/kernel/-/issues/12305


Build changes
-------------

  * Linux: CI_DRM_15602 -> Patchwork_140538v1

  CI-20190529: 20190529
  CI_DRM_15602: 24707cf2a7c47d4cd192c97e73d58aa4011de154 @ git://anongit.freedesktop.org/gfx-ci/linux
  IGT_8086: 18939acec2446c6644644186b090d16e366af8bc @ https://gitlab.freedesktop.org/drm/igt-gpu-tools.git
  Patchwork_140538v1: 24707cf2a7c47d4cd192c97e73d58aa4011de154 @ git://anongit.freedesktop.org/gfx-ci/linux

== Logs ==

For more details see: https://intel-gfx-ci.01.org/tree/drm-tip/Patchwork_140538v1/index.html

[-- Attachment #2: Type: text/html, Size: 4473 bytes --]

[PATCH 0/3] drm/xe: Fix races on fdinfo

[Lucas De Marchi]

[ I sent this yesterday to the i915 mailing list only:
  https://patchwork.freedesktop.org/series/140538/
  Re-sending to the right one ]

The current reading of engine utilization has same races. This should
fix most of them while also drastically reducing the update rate needed
on "normal apps".

I left tests/xe_drm_fdinfo running on 2 systems and saw no failures
after 100 iterations.

Lucas De Marchi (3):
  drm/xe: Add trace to lrc timestamp update
  drm/xe: Accumulate exec queue timestamp on destroy
  drm/xe: Stop accumulating LRC timestamp on job_free

 drivers/gpu/drm/xe/Makefile        |  1 +
 drivers/gpu/drm/xe/xe_exec_queue.c | 14 ++++++++
 drivers/gpu/drm/xe/xe_guc_submit.c |  2 --
 drivers/gpu/drm/xe/xe_lrc.c        |  3 ++
 drivers/gpu/drm/xe/xe_trace_lrc.c  |  9 ++++++
 drivers/gpu/drm/xe/xe_trace_lrc.h  | 52 ++++++++++++++++++++++++++++++
 6 files changed, 79 insertions(+), 2 deletions(-)
 create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.c
 create mode 100644 drivers/gpu/drm/xe/xe_trace_lrc.h

-- 
2.47.0

[PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Lucas De Marchi]

When the exec queue is destroyed, there's a race between a query to the
fdinfo and the exec queue value being updated: after the destroy ioctl,
if the fdinfo is queried before a call to guc_exec_queue_free_job(),
the wrong utilization is reported: it's not accumulated on the query
since the queue was removed from the array, and the value wasn't updated
yet by the free_job().

Explicitly accumulate the engine utilization so the right value is
visible after the ioctl return.

Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
---
 drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
index d098d2dd1b2d..b15ca84b2422 100644
--- a/drivers/gpu/drm/xe/xe_exec_queue.c
+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
@@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
 
 	xe_exec_queue_kill(q);
 
+	/*
+	 * After killing and destroying the exec queue, make sure userspace has
+	 * an updated view of the run ticks, regardless if this was the last
+	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
+	 * query to fdinfo after this returns could not account for this load.
+	 */
+	xe_exec_queue_update_run_ticks(q);
+
 	trace_xe_exec_queue_close(q);
 	xe_exec_queue_put(q);
 
-- 
2.47.0

RE: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Cavitt, Jonathan]

-----Original Message-----
From: De Marchi, Lucas <lucas.demarchi@intel.com> 
Sent: Saturday, October 26, 2024 10:09 AM
To: intel-xe@lists.freedesktop.org
Cc: Cavitt, Jonathan <jonathan.cavitt@intel.com>; Nerlige Ramappa, Umesh <umesh.nerlige.ramappa@intel.com>; De Marchi, Lucas <lucas.demarchi@intel.com>
Subject: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy
> 
> When the exec queue is destroyed, there's a race between a query to the
> fdinfo and the exec queue value being updated: after the destroy ioctl,
> if the fdinfo is queried before a call to guc_exec_queue_free_job(),
> the wrong utilization is reported: it's not accumulated on the query
> since the queue was removed from the array, and the value wasn't updated
> yet by the free_job().
> 
> Explicitly accumulate the engine utilization so the right value is
> visible after the ioctl return.
> 
> Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
> Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
> Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>

LGTM
Reviewed-by: Jonathan Cavitt <jonathan.cavitt@intel.com>
-Jonathan Cavitt

> ---
>  drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
> index d098d2dd1b2d..b15ca84b2422 100644
> --- a/drivers/gpu/drm/xe/xe_exec_queue.c
> +++ b/drivers/gpu/drm/xe/xe_exec_queue.c
> @@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>  
>  	xe_exec_queue_kill(q);
>  
> +	/*
> +	 * After killing and destroying the exec queue, make sure userspace has
> +	 * an updated view of the run ticks, regardless if this was the last
> +	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
> +	 * query to fdinfo after this returns could not account for this load.
> +	 */
> +	xe_exec_queue_update_run_ticks(q);
> +
>  	trace_xe_exec_queue_close(q);
>  	xe_exec_queue_put(q);
>  
> -- 
> 2.47.0
> 
> 

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Umesh Nerlige Ramappa]

On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
>When the exec queue is destroyed, there's a race between a query to the
>fdinfo and the exec queue value being updated: after the destroy ioctl,
>if the fdinfo is queried before a call to guc_exec_queue_free_job(),
>the wrong utilization is reported: it's not accumulated on the query
>since the queue was removed from the array, and the value wasn't updated
>yet by the free_job().
>
>Explicitly accumulate the engine utilization so the right value is
>visible after the ioctl return.
>
>Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
>Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
>Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
>---
> drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
> 1 file changed, 8 insertions(+)
>
>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>index d098d2dd1b2d..b15ca84b2422 100644
>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
>@@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>
> 	xe_exec_queue_kill(q);
>
>+	/*
>+	 * After killing and destroying the exec queue, make sure userspace has
>+	 * an updated view of the run ticks, regardless if this was the last
>+	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
>+	 * query to fdinfo after this returns could not account for this load.
>+	 */
>+	xe_exec_queue_update_run_ticks(q);
>+

At this point we may/may-not have the updated LRC timestamp.

fwiu, xe_exec_queue_kill() is an async call. It will queue a work that 
will disable guc scheduling on the context. Once guc notifies KMD that 
scheduling is disabled on this context, KMD knows for sure that the 
context has switched out and the lrc timestamp is updated for this 
context. It may work well for contexts that switch frequently and may 
not work for contexts that seldom switch or never destroy their exec 
queue.

I still believe calling it from job free is the right thing to do. As 
for the ~120 Hz updates, these are just memory updates, so not sure if 
it's a huge performance impact.

If the ftrace is getting filed up, we could throttle that.

Thanks,
Umesh

> 	trace_xe_exec_queue_close(q);
> 	xe_exec_queue_put(q);
>
>-- 
>2.47.0
>

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Matthew Brost]

On Mon, Oct 28, 2024 at 01:33:09PM -0700, Umesh Nerlige Ramappa wrote:
> On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
> > When the exec queue is destroyed, there's a race between a query to the
> > fdinfo and the exec queue value being updated: after the destroy ioctl,
> > if the fdinfo is queried before a call to guc_exec_queue_free_job(),
> > the wrong utilization is reported: it's not accumulated on the query
> > since the queue was removed from the array, and the value wasn't updated
> > yet by the free_job().
> > 
> > Explicitly accumulate the engine utilization so the right value is
> > visible after the ioctl return.
> > 
> > Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
> > Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
> > Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
> > ---
> > drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
> > 1 file changed, 8 insertions(+)
> > 
> > diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
> > index d098d2dd1b2d..b15ca84b2422 100644
> > --- a/drivers/gpu/drm/xe/xe_exec_queue.c
> > +++ b/drivers/gpu/drm/xe/xe_exec_queue.c
> > @@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
> > 
> > 	xe_exec_queue_kill(q);
> > 
> > +	/*
> > +	 * After killing and destroying the exec queue, make sure userspace has
> > +	 * an updated view of the run ticks, regardless if this was the last
> > +	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
> > +	 * query to fdinfo after this returns could not account for this load.
> > +	 */
> > +	xe_exec_queue_update_run_ticks(q);
> > +
> 
> At this point we may/may-not have the updated LRC timestamp.
> 
> fwiu, xe_exec_queue_kill() is an async call. It will queue a work that will
> disable guc scheduling on the context. Once guc notifies KMD that scheduling
> is disabled on this context, KMD knows for sure that the context has
> switched out and the lrc timestamp is updated for this context. It may work
> well for contexts that switch frequently and may not work for contexts that
> seldom switch or never destroy their exec queue.
> 
> I still believe calling it from job free is the right thing to do. As for
> the ~120 Hz updates, these are just memory updates, so not sure if it's a
> huge performance impact.
> 

I agree with Umesh here - unsure why it is a big deal to update the
busyness in free_job.

Also the timestamp counters can wrap and if they are sampled frequently
enough a wrap will be missed.

Matt

> If the ftrace is getting filed up, we could throttle that.
> 
> Thanks,
> Umesh
> 
> > 	trace_xe_exec_queue_close(q);
> > 	xe_exec_queue_put(q);
> > 
> > -- 
> > 2.47.0
> > 

RE: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Cavitt, Jonathan]

-----Original Message-----
From: Brost, Matthew <matthew.brost@intel.com> 
Sent: Monday, October 28, 2024 2:59 PM
To: Nerlige Ramappa, Umesh <umesh.nerlige.ramappa@intel.com>
Cc: De Marchi, Lucas <lucas.demarchi@intel.com>; intel-xe@lists.freedesktop.org; Cavitt, Jonathan <jonathan.cavitt@intel.com>
Subject: Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy
> 
> On Mon, Oct 28, 2024 at 01:33:09PM -0700, Umesh Nerlige Ramappa wrote:
> > On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
> > > When the exec queue is destroyed, there's a race between a query to the
> > > fdinfo and the exec queue value being updated: after the destroy ioctl,
> > > if the fdinfo is queried before a call to guc_exec_queue_free_job(),
> > > the wrong utilization is reported: it's not accumulated on the query
> > > since the queue was removed from the array, and the value wasn't updated
> > > yet by the free_job().
> > > 
> > > Explicitly accumulate the engine utilization so the right value is
> > > visible after the ioctl return.
> > > 
> > > Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
> > > Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
> > > Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
> > > ---
> > > drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
> > > 1 file changed, 8 insertions(+)
> > > 
> > > diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
> > > index d098d2dd1b2d..b15ca84b2422 100644
> > > --- a/drivers/gpu/drm/xe/xe_exec_queue.c
> > > +++ b/drivers/gpu/drm/xe/xe_exec_queue.c
> > > @@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
> > > 
> > > 	xe_exec_queue_kill(q);
> > > 
> > > +	/*
> > > +	 * After killing and destroying the exec queue, make sure userspace has
> > > +	 * an updated view of the run ticks, regardless if this was the last
> > > +	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
> > > +	 * query to fdinfo after this returns could not account for this load.
> > > +	 */
> > > +	xe_exec_queue_update_run_ticks(q);
> > > +
> > 
> > At this point we may/may-not have the updated LRC timestamp.
> > 
> > fwiu, xe_exec_queue_kill() is an async call. It will queue a work that will
> > disable guc scheduling on the context. Once guc notifies KMD that scheduling
> > is disabled on this context, KMD knows for sure that the context has
> > switched out and the lrc timestamp is updated for this context. It may work
> > well for contexts that switch frequently and may not work for contexts that
> > seldom switch or never destroy their exec queue.
> > 
> > I still believe calling it from job free is the right thing to do. As for
> > the ~120 Hz updates, these are just memory updates, so not sure if it's a
> > huge performance impact.
> > 
> 
> I agree with Umesh here - unsure why it is a big deal to update the
> busyness in free_job.

I might be misreading this, but I'm fairly certain Umesh is saying that we
*should* be updating the busyness in free_job, not that whether we do
so or not is of no consequence.

Not that I particularly agree with that sentiment, mind.  Actually, I think
you and I agree that we should only be updating the busyness here and
when querying the busyness as a part of the fdinfo query.

Please correct me if I'm misunderstanding.
-Jonathan Cavitt

> 
> Also the timestamp counters can wrap and if they are sampled frequently
> enough a wrap will be missed.
> 
> Matt
> 
> > If the ftrace is getting filed up, we could throttle that.
> > 
> > Thanks,
> > Umesh
> > 
> > > 	trace_xe_exec_queue_close(q);
> > > 	xe_exec_queue_put(q);
> > > 
> > > -- 
> > > 2.47.0
> > > 
> 

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Lucas De Marchi]

On Mon, Oct 28, 2024 at 09:59:18PM +0000, Matthew Brost wrote:
>On Mon, Oct 28, 2024 at 01:33:09PM -0700, Umesh Nerlige Ramappa wrote:
>> On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
>> > When the exec queue is destroyed, there's a race between a query to the
>> > fdinfo and the exec queue value being updated: after the destroy ioctl,
>> > if the fdinfo is queried before a call to guc_exec_queue_free_job(),
>> > the wrong utilization is reported: it's not accumulated on the query
>> > since the queue was removed from the array, and the value wasn't updated
>> > yet by the free_job().
>> >
>> > Explicitly accumulate the engine utilization so the right value is
>> > visible after the ioctl return.
>> >
>> > Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
>> > Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
>> > Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
>> > ---
>> > drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
>> > 1 file changed, 8 insertions(+)
>> >
>> > diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>> > index d098d2dd1b2d..b15ca84b2422 100644
>> > --- a/drivers/gpu/drm/xe/xe_exec_queue.c
>> > +++ b/drivers/gpu/drm/xe/xe_exec_queue.c
>> > @@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>> >
>> > 	xe_exec_queue_kill(q);
>> >
>> > +	/*
>> > +	 * After killing and destroying the exec queue, make sure userspace has
>> > +	 * an updated view of the run ticks, regardless if this was the last
>> > +	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
>> > +	 * query to fdinfo after this returns could not account for this load.
>> > +	 */
>> > +	xe_exec_queue_update_run_ticks(q);
>> > +
>>
>> At this point we may/may-not have the updated LRC timestamp.
>>
>> fwiu, xe_exec_queue_kill() is an async call. It will queue a work that will
>> disable guc scheduling on the context. Once guc notifies KMD that scheduling
>> is disabled on this context, KMD knows for sure that the context has
>> switched out and the lrc timestamp is updated for this context. It may work
>> well for contexts that switch frequently and may not work for contexts that
>> seldom switch or never destroy their exec queue.
>>
>> I still believe calling it from job free is the right thing to do. As for
>> the ~120 Hz updates, these are just memory updates, so not sure if it's a

these are io accesses. Buffer is potentially in vram so it's not just
memory updates.

>> huge performance impact.
>>
>
>I agree with Umesh here - unsure why it is a big deal to update the
>busyness in free_job.
>
>Also the timestamp counters can wrap and if they are sampled frequently
>enough a wrap will be missed.

I don't think we have any use case in which userspace is sampling once
every 200sec. Use case here is rather top-like apps that are doing it
once per second or so. Worst case scenario if we have a real use case is
we'd update it at 1/60 Hz rather than doing it at 120Hz per client.

I still have memories of these small but frequent io traffic causing
problems. See commit 59bcdb564b3b ("drm/i915/guc: Don't update engine busyness
stats too frequently")... internal iterations of that overlapped with my
conversion to iosys_map which were initially pointed as culprit, if my
memory serves well. I don't remember how frequent we were talking about
on gt park/unpark though. Maybe Alan does, Cc'ing him.

Lucas De Marchi

>
>Matt
>
>> If the ftrace is getting filed up, we could throttle that.
>>
>> Thanks,
>> Umesh
>>
>> > 	trace_xe_exec_queue_close(q);
>> > 	xe_exec_queue_put(q);
>> >
>> > --
>> > 2.47.0
>> >

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Lucas De Marchi]

On Mon, Oct 28, 2024 at 01:33:09PM -0700, Umesh Nerlige Ramappa wrote:
>On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
>>When the exec queue is destroyed, there's a race between a query to the
>>fdinfo and the exec queue value being updated: after the destroy ioctl,
>>if the fdinfo is queried before a call to guc_exec_queue_free_job(),
>>the wrong utilization is reported: it's not accumulated on the query
>>since the queue was removed from the array, and the value wasn't updated
>>yet by the free_job().
>>
>>Explicitly accumulate the engine utilization so the right value is
>>visible after the ioctl return.
>>
>>Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
>>Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
>>Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
>>---
>>drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
>>1 file changed, 8 insertions(+)
>>
>>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>>index d098d2dd1b2d..b15ca84b2422 100644
>>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>>+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
>>@@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>>
>>	xe_exec_queue_kill(q);
>>
>>+	/*
>>+	 * After killing and destroying the exec queue, make sure userspace has
>>+	 * an updated view of the run ticks, regardless if this was the last
>>+	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
>>+	 * query to fdinfo after this returns could not account for this load.
>>+	 */
>>+	xe_exec_queue_update_run_ticks(q);
>>+
>
>At this point we may/may-not have the updated LRC timestamp.
>
>fwiu, xe_exec_queue_kill() is an async call. It will queue a work that 
>will disable guc scheduling on the context. Once guc notifies KMD that 
>scheduling is disabled on this context, KMD knows for sure that the 
>context has switched out and the lrc timestamp is updated for this 

ok. do you know what's that notification? Is it the cleanup that we
process at __guc_exec_queue_process_msg_cleanup() ?  (which is where I'm
moving the io read to in the other patch)

>context. It may work well for contexts that switch frequently and may 
>not work for contexts that seldom switch or never destroy their exec 
>queue.

why does it matter? it's only for contexts going away - for context that
are scheduled out the sampling on fdinfo read covers it. Note that this
call is not replacing other calls. If the exec queue is not destroyed,
the other 2 places should still cover it.

The problem with the case when the destroy ioctl is called is that q is
removed from xef->exec_queue.xa, so the additional call in fdinfo-read stops
working. It  then relies on the last job completing and being released before
a read on the fdinfo. As CI shows, this is racy and fails in ~10% of
the cases.

On a remote system I got it was failing ~20% of the time

>
>I still believe calling it from job free is the right thing to do. As 
>for the ~120 Hz updates, these are just memory updates, so not sure if 
>it's a huge performance impact.

it seems now you are commenting on the change in the other patch?

I think it's pretty pointless to do the io access when nobody cares
about that number. The user needs to be reading the fdinfo, probably
through gputop or the like for the number to be meaningful. So why do we
care about sampling it at a high frequency when nobody is looking? For
real, non-CI use-cases it should be as good as before.  The difference
is that instead of getting 120 updates of few cycles, we are getting
just 1 with the amount of cycles that got used in the last sampling
period.

Looking at the traces we do get a few low-msec execution time for
xe_lrc_update_timestamp(). Mind you, there's another race about updating
u32 in xef in a non-atomic way and doing it that frequently just makes
it more likely to happen. That still needs a separate fix.

Goal of this series is to make this work:

	$ for ((i=0; i < 100; i++)); do echo $i/100 >&2; if ! ./build/tests/xe_drm_fdinfo; then break; fi; done

I was happy when sending this that it passed. But just double checking
on another host, the issue is still there and I get this after 16
iterations:

Starting subtest: utilization-single-full-load-destroy-queue
....
(xe_drm_fdinfo:5997) DEBUG: vcs: spinner ended (timestamp=4818209)
(xe_drm_fdinfo:5997) DEBUG: vcs: sample 1: cycles 9637999, total_cycles 19272820538
(xe_drm_fdinfo:5997) DEBUG: vcs: sample 2: cycles 9637999, total_cycles 19277703269
(xe_drm_fdinfo:5997) DEBUG: vcs: percent: 0.000000
(xe_drm_fdinfo:5997) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:527:
(xe_drm_fdinfo:5997) CRITICAL: Failed assertion: 95.0 < percent
(xe_drm_fdinfo:5997) CRITICAL: error: 95.000000 >= 0.000000
(xe_drm_fdinfo:5997) igt_core-INFO: Stack trace:
(xe_drm_fdinfo:5997) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(xe_drm_fdinfo:5997) igt_core-INFO:   #1 [check_results+0x204]
(xe_drm_fdinfo:5997) igt_core-INFO:   #2 ../tests/intel/xe_drm_fdinfo.c:860 __igt_unique____real_main806()
(xe_drm_fdinfo:5997) igt_core-INFO:   #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
(xe_drm_fdinfo:5997) igt_core-INFO:   #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(xe_drm_fdinfo:5997) igt_core-INFO:   #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(xe_drm_fdinfo:5997) igt_core-INFO:   #6 [_start+0x25]
****  END  ****

which makes me think it's probably related to the kill being async as
you mentioned.

I wonder if we should synchronize the call in the fdinfo read with the
queues that are going away.

Another thought I had was to use the wabb, but afaics we can only
execute something on context restore, not on context save.

>
>If the ftrace is getting filed up, we could throttle that.

oh no, that is definitely not what I want. If we enable the tracepoint, we
want to see it, not artifically drop the events.

Initially (and to get a good measure of function runtime), I was
actually using retsnoop rather than using the previously non-existent
tracepoint:

	retsnoop -e xe_lrc_update_timestamp -e xe_lrc_create -e xe_lrc_destroy  -S -A -C args.fmt-max-arg-width=0

Lucas De Marchi

>
>Thanks,
>Umesh
>
>>	trace_xe_exec_queue_close(q);
>>	xe_exec_queue_put(q);
>>
>>-- 
>>2.47.0
>>

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Umesh Nerlige Ramappa]

On Mon, Oct 28, 2024 at 05:32:03PM -0500, Lucas De Marchi wrote:
>On Mon, Oct 28, 2024 at 01:33:09PM -0700, Umesh Nerlige Ramappa wrote:
>>On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
>>>When the exec queue is destroyed, there's a race between a query to the
>>>fdinfo and the exec queue value being updated: after the destroy ioctl,
>>>if the fdinfo is queried before a call to guc_exec_queue_free_job(),
>>>the wrong utilization is reported: it's not accumulated on the query
>>>since the queue was removed from the array, and the value wasn't updated
>>>yet by the free_job().
>>>
>>>Explicitly accumulate the engine utilization so the right value is
>>>visible after the ioctl return.
>>>
>>>Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
>>>Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
>>>Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
>>>---
>>>drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
>>>1 file changed, 8 insertions(+)
>>>
>>>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>>>index d098d2dd1b2d..b15ca84b2422 100644
>>>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>>>++ b/drivers/gpu/drm/xe/xe_exec_quee.c
>>>@@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>>>
>>>	xe_exec_queue_kill(q);
>>>
>>>+	/*
>>>+	 * After killing and destroying the exec queue, make sure userspace has
>>>+	 * an updated view of the run ticks, regardless if this was the last
>>>+	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
>>>+	 * query to fdinfo after this returns could not account for this load.
>>>+	 */
>>>+	xe_exec_queue_update_run_ticks(q);
>>>+
>>
>>At this point we may/may-not have the updated LRC timestamp.
>>
>>fwiu, xe_exec_queue_kill() is an async call. It will queue a work 
>>that will disable guc scheduling on the context. Once guc notifies 
>>KMD that scheduling is disabled on this context, KMD knows for sure 
>>that the context has switched out and the lrc timestamp is updated 
>>for this
>
>ok. do you know what's that notification? Is it the cleanup that we
>process at __guc_exec_queue_process_msg_cleanup() ?  (which is where I'm
>moving the io read to in the other patch)
>
>>context. It may work well for contexts that switch frequently and 
>>may not work for contexts that seldom switch or never destroy their 
>>exec queue.
>
>why does it matter? it's only for contexts going away - for context that
>are scheduled out the sampling on fdinfo read covers it. Note that this
>call is not replacing other calls. If the exec queue is not destroyed,
>the other 2 places should still cover it.
>
>The problem with the case when the destroy ioctl is called is that q is
>removed from xef->exec_queue.xa, so the additional call in fdinfo-read stops
>working. It  then relies on the last job completing and being released before
>a read on the fdinfo. As CI shows, this is racy and fails in ~10% of
>the cases.
>
>On a remote system I got it was failing ~20% of the time
>
>>
>>I still believe calling it from job free is the right thing to do. 
>>As for the ~120 Hz updates, these are just memory updates, so not 
>>sure if it's a huge performance impact.
>
>it seems now you are commenting on the change in the other patch?

sorry, I will try to be more clear here.

patch 3/3:

I missed the fact that the updates could be in VRAM, so moving the 
update out of job_free makes sense. 

Also since fdinfo query is expected to be frequent enough, adding the update 
to exec_queue_fini makes sense too.

patch 2/3 (everything below)

it's just the update in destroy_ioctl that I am not convinced about since 
the kill is async. Also you see another instance of failure already below.

>
>I think it's pretty pointless to do the io access when nobody cares
>about that number. The user needs to be reading the fdinfo, probably
>through gputop or the like for the number to be meaningful. So why do we
>care about sampling it at a high frequency when nobody is looking? For
>real, non-CI use-cases it should be as good as before.  The difference
>is that instead of getting 120 updates of few cycles, we are getting
>just 1 with the amount of cycles that got used in the last sampling
>period.
>
>Looking at the traces we do get a few low-msec execution time for
>xe_lrc_update_timestamp(). Mind you, there's another race about updating
>u32 in xef in a non-atomic way and doing it that frequently just makes
>it more likely to happen. That still needs a separate fix.
>
>Goal of this series is to make this work:
>
>	$ for ((i=0; i < 100; i++)); do echo $i/100 >&2; if ! ./build/tests/xe_drm_fdinfo; then break; fi; done
>
>I was happy when sending this that it passed. But just double checking
>on another host, the issue is still there and I get this after 16
>iterations:
>
>Starting subtest: utilization-single-full-load-destroy-queue
>....
>(xe_drm_fdinfo:5997) DEBUG: vcs: spinner ended (timestamp=4818209)
>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 1: cycles 9637999, total_cycles 19272820538
>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 2: cycles 9637999, total_cycles 19277703269
>(xe_drm_fdinfo:5997) DEBUG: vcs: percent: 0.000000
>(xe_drm_fdinfo:5997) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:527:
>(xe_drm_fdinfo:5997) CRITICAL: Failed assertion: 95.0 < percent
>(xe_drm_fdinfo:5997) CRITICAL: error: 95.000000 >= 0.000000
>(xe_drm_fdinfo:5997) igt_core-INFO: Stack trace:
>(xe_drm_fdinfo:5997) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>(xe_drm_fdinfo:5997) igt_core-INFO:   #1 [check_results+0x204]
>(xe_drm_fdinfo:5997) igt_core-INFO:   #2 ../tests/intel/xe_drm_fdinfo.c:860 __igt_unique____real_main806()
>(xe_drm_fdinfo:5997) igt_core-INFO:   #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>(xe_drm_fdinfo:5997) igt_core-INFO:   #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>(xe_drm_fdinfo:5997) igt_core-INFO:   #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>(xe_drm_fdinfo:5997) igt_core-INFO:   #6 [_start+0x25]
>****  END  ****
>
>which makes me think it's probably related to the kill being async as
>you mentioned.
>
>I wonder if we should synchronize the call in the fdinfo read with the
>queues that are going away.

Hmm, maybe.

I was of the opinion that we should solve it in Xe by adding an update call 
in an additional place (like you are doing), but after digging into it a 
bit, I am not sure if we should resolve this specific issue. Instead, we 
should alter the test to not check for accuracy when the queue is destroyed 
before taking the second sample. We know that the ticks will get 
updated at some reasonable point in future and the user will see it in 
subsequent fdinfo queries anyways. If that "reasonable point in future" is 
unacceptably large, then I think the problem is outside the PCEU domain.

Note that the original reason we added the test was to catch the ref count 
issue with xef object (which is now fixed).

>
>Another thought I had was to use the wabb, but afaics we can only
>execute something on context restore, not on context save.

I am curious what you want to run in context save though and how it's any 
different from what's happening now - CTX_TIMESTAMP is being updated on 
save.

>
>>
>>If the ftrace is getting filed up, we could throttle that.
>
>oh no, that is definitely not what I want. If we enable the tracepoint, we
>want to see it, not artifically drop the events.
>
>Initially (and to get a good measure of function runtime), I was
>actually using retsnoop rather than using the previously non-existent
>tracepoint:
>
>	retsnoop -e xe_lrc_update_timestamp -e xe_lrc_create -e xe_lrc_destroy  -S -A -C args.fmt-max-arg-width=0

Didn't know that. That's ^ useful.

Thanks,
Umesh
>
>Lucas De Marchi
>
>>
>>Thanks,
>>Umesh
>>
>>>	trace_xe_exec_queue_close(q);
>>>	xe_exec_queue_put(q);
>>>
>>>-- 
>>>2.47.0
>>>

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Lucas De Marchi]

On Tue, Oct 29, 2024 at 10:27:28AM -0700, Umesh Nerlige Ramappa wrote:
>On Mon, Oct 28, 2024 at 05:32:03PM -0500, Lucas De Marchi wrote:
>>On Mon, Oct 28, 2024 at 01:33:09PM -0700, Umesh Nerlige Ramappa wrote:
>>>On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
>>>>When the exec queue is destroyed, there's a race between a query to the
>>>>fdinfo and the exec queue value being updated: after the destroy ioctl,
>>>>if the fdinfo is queried before a call to guc_exec_queue_free_job(),
>>>>the wrong utilization is reported: it's not accumulated on the query
>>>>since the queue was removed from the array, and the value wasn't updated
>>>>yet by the free_job().
>>>>
>>>>Explicitly accumulate the engine utilization so the right value is
>>>>visible after the ioctl return.
>>>>
>>>>Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
>>>>Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
>>>>Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
>>>>---
>>>>drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
>>>>1 file changed, 8 insertions(+)
>>>>
>>>>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>>>>index d098d2dd1b2d..b15ca84b2422 100644
>>>>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>>>>++ b/drivers/gpu/drm/xe/xe_exec_quee.c
>>>>@@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>>>>
>>>>	xe_exec_queue_kill(q);
>>>>
>>>>+	/*
>>>>+	 * After killing and destroying the exec queue, make sure userspace has
>>>>+	 * an updated view of the run ticks, regardless if this was the last
>>>>+	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
>>>>+	 * query to fdinfo after this returns could not account for this load.
>>>>+	 */
>>>>+	xe_exec_queue_update_run_ticks(q);
>>>>+
>>>
>>>At this point we may/may-not have the updated LRC timestamp.
>>>
>>>fwiu, xe_exec_queue_kill() is an async call. It will queue a work 
>>>that will disable guc scheduling on the context. Once guc notifies 
>>>KMD that scheduling is disabled on this context, KMD knows for 
>>>sure that the context has switched out and the lrc timestamp is 
>>>updated for this
>>
>>ok. do you know what's that notification? Is it the cleanup that we
>>process at __guc_exec_queue_process_msg_cleanup() ?  (which is where I'm
>>moving the io read to in the other patch)
>>
>>>context. It may work well for contexts that switch frequently and 
>>>may not work for contexts that seldom switch or never destroy 
>>>their exec queue.
>>
>>why does it matter? it's only for contexts going away - for context that
>>are scheduled out the sampling on fdinfo read covers it. Note that this
>>call is not replacing other calls. If the exec queue is not destroyed,
>>the other 2 places should still cover it.
>>
>>The problem with the case when the destroy ioctl is called is that q is
>>removed from xef->exec_queue.xa, so the additional call in fdinfo-read stops
>>working. It  then relies on the last job completing and being released before
>>a read on the fdinfo. As CI shows, this is racy and fails in ~10% of
>>the cases.
>>
>>On a remote system I got it was failing ~20% of the time
>>
>>>
>>>I still believe calling it from job free is the right thing to do. 
>>>As for the ~120 Hz updates, these are just memory updates, so not 
>>>sure if it's a huge performance impact.
>>
>>it seems now you are commenting on the change in the other patch?
>
>sorry, I will try to be more clear here.
>
>patch 3/3:
>
>I missed the fact that the updates could be in VRAM, so moving the 
>update out of job_free makes sense.
>
>Also since fdinfo query is expected to be frequent enough, adding the 
>update to exec_queue_fini makes sense too.
>
>patch 2/3 (everything below)
>
>it's just the update in destroy_ioctl that I am not convinced about 
>since the kill is async. Also you see another instance of failure 
>already below.
>
>>
>>I think it's pretty pointless to do the io access when nobody cares
>>about that number. The user needs to be reading the fdinfo, probably
>>through gputop or the like for the number to be meaningful. So why do we
>>care about sampling it at a high frequency when nobody is looking? For
>>real, non-CI use-cases it should be as good as before.  The difference
>>is that instead of getting 120 updates of few cycles, we are getting
>>just 1 with the amount of cycles that got used in the last sampling
>>period.
>>
>>Looking at the traces we do get a few low-msec execution time for
>>xe_lrc_update_timestamp(). Mind you, there's another race about updating
>>u32 in xef in a non-atomic way and doing it that frequently just makes
>>it more likely to happen. That still needs a separate fix.
>>
>>Goal of this series is to make this work:
>>
>>	$ for ((i=0; i < 100; i++)); do echo $i/100 >&2; if ! ./build/tests/xe_drm_fdinfo; then break; fi; done
>>
>>I was happy when sending this that it passed. But just double checking
>>on another host, the issue is still there and I get this after 16
>>iterations:
>>
>>Starting subtest: utilization-single-full-load-destroy-queue
>>....
>>(xe_drm_fdinfo:5997) DEBUG: vcs: spinner ended (timestamp=4818209)
>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 1: cycles 9637999, total_cycles 19272820538
>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 2: cycles 9637999, total_cycles 19277703269
>>(xe_drm_fdinfo:5997) DEBUG: vcs: percent: 0.000000
>>(xe_drm_fdinfo:5997) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:527:
>>(xe_drm_fdinfo:5997) CRITICAL: Failed assertion: 95.0 < percent
>>(xe_drm_fdinfo:5997) CRITICAL: error: 95.000000 >= 0.000000
>>(xe_drm_fdinfo:5997) igt_core-INFO: Stack trace:
>>(xe_drm_fdinfo:5997) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>>(xe_drm_fdinfo:5997) igt_core-INFO:   #1 [check_results+0x204]
>>(xe_drm_fdinfo:5997) igt_core-INFO:   #2 ../tests/intel/xe_drm_fdinfo.c:860 __igt_unique____real_main806()
>>(xe_drm_fdinfo:5997) igt_core-INFO:   #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>>(xe_drm_fdinfo:5997) igt_core-INFO:   #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>>(xe_drm_fdinfo:5997) igt_core-INFO:   #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>>(xe_drm_fdinfo:5997) igt_core-INFO:   #6 [_start+0x25]
>>****  END  ****
>>
>>which makes me think it's probably related to the kill being async as
>>you mentioned.
>>
>>I wonder if we should synchronize the call in the fdinfo read with the
>>queues that are going away.
>
>Hmm, maybe.

doing that it passes for me 62/100 running all
xe_drm_fdinfo@utilization-* tests.

The failure on run 63 is different  and I think it's another bug or
race. This is what I'm testing with currently:

diff --git a/drivers/gpu/drm/xe/xe_device_types.h b/drivers/gpu/drm/xe/xe_device_types.h
index a3e777ad281e3..eaee19efeadce 100644
--- a/drivers/gpu/drm/xe/xe_device_types.h
+++ b/drivers/gpu/drm/xe/xe_device_types.h
@@ -614,6 +614,11 @@ struct xe_file {
                  * does things while being held.
                  */
                 struct mutex lock;
+               /**
+                * @exec_queue.pending_removal: items pending to be removed to
+                * synchronize GPU state update with ongoing query.
+                */
+               atomic_t pending_removal;
         } exec_queue;
  
         /** @run_ticks: hw engine class run time in ticks for this drm client */
diff --git a/drivers/gpu/drm/xe/xe_drm_client.c b/drivers/gpu/drm/xe/xe_drm_client.c
index a9b0d640b2581..5f6347d12eec5 100644
--- a/drivers/gpu/drm/xe/xe_drm_client.c
+++ b/drivers/gpu/drm/xe/xe_drm_client.c
@@ -327,6 +327,13 @@ static void show_run_ticks(struct drm_printer *p, struct drm_file *file)
         if (!read_total_gpu_timestamp(xe, &gpu_timestamp))
                 goto fail_gpu_timestamp;
  
+       /*
+        * Wait for any exec queue going away: their cycles will get updated on
+        * context switch out, so wait for that to happen
+        */
+        wait_var_event(&xef->exec_queue.pending_removal,
+                       !atomic_read(&xef->exec_queue.pending_removal));
+
         xe_pm_runtime_put(xe);
  
         for (class = 0; class < XE_ENGINE_CLASS_MAX; class++) {
diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
index fd0f3b3c9101d..58dd35beb15ad 100644
--- a/drivers/gpu/drm/xe/xe_exec_queue.c
+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
@@ -262,8 +262,11 @@ void xe_exec_queue_fini(struct xe_exec_queue *q)
  
         /*
          * Before releasing our ref to lrc and xef, accumulate our run ticks
+        * and wakeup any waiters.
          */
         xe_exec_queue_update_run_ticks(q);
+       if (q->xef && atomic_dec_and_test(&q->xef->exec_queue.pending_removal))
+               wake_up_var(&q->xef->exec_queue.pending_removal);
  
         for (i = 0; i < q->width; ++i)
                 xe_lrc_put(q->lrc[i]);
@@ -824,6 +827,7 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
             XE_IOCTL_DBG(xe, args->reserved[0] || args->reserved[1]))
                 return -EINVAL;
  
+       atomic_inc(&xef->exec_queue.pending_removal);
         mutex_lock(&xef->exec_queue.lock);
         q = xa_erase(&xef->exec_queue.xa, args->exec_queue_id);
         mutex_unlock(&xef->exec_queue.lock);


Idea is that any process reading the fdinfo needs to wait on contexts
going away via kill.


>
>I was of the opinion that we should solve it in Xe by adding an update 
>call in an additional place (like you are doing), but after digging 
>into it a bit, I am not sure if we should resolve this specific issue. 
>Instead, we should alter the test to not check for accuracy when the 
>queue is destroyed before taking the second sample. We know that the 
>ticks will get updated at some reasonable point in future and the user 
>will see it in subsequent fdinfo queries anyways. If that "reasonable 
>point in future" is unacceptably large, then I think the problem is 
>outside the PCEU domain.
>
>Note that the original reason we added the test was to catch the ref 
>count issue with xef object (which is now fixed).
>
>>
>>Another thought I had was to use the wabb, but afaics we can only
>>execute something on context restore, not on context save.
>
>I am curious what you want to run in context save though and how it's 
>any different from what's happening now - CTX_TIMESTAMP is being 
>updated on save.

I was thinking about letting the gpu use MI_MATH to keep calculating
the delta.... but yeah, it wouldn't help in this particular case.


>
>>
>>>
>>>If the ftrace is getting filed up, we could throttle that.
>>
>>oh no, that is definitely not what I want. If we enable the tracepoint, we
>>want to see it, not artifically drop the events.
>>
>>Initially (and to get a good measure of function runtime), I was
>>actually using retsnoop rather than using the previously non-existent
>>tracepoint:
>>
>>	retsnoop -e xe_lrc_update_timestamp -e xe_lrc_create -e xe_lrc_destroy  -S -A -C args.fmt-max-arg-width=0
>
>Didn't know that. That's ^ useful.

life saver - I keep forgetting options for the other tools to do similar
stuff, but this one is so simple and effective.

Lucas De Marchi

>
>Thanks,
>Umesh
>>
>>Lucas De Marchi
>>
>>>
>>>Thanks,
>>>Umesh
>>>
>>>>	trace_xe_exec_queue_close(q);
>>>>	xe_exec_queue_put(q);
>>>>
>>>>-- 
>>>>2.47.0
>>>>

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Umesh Nerlige Ramappa]

On Tue, Oct 29, 2024 at 12:58:35PM -0500, Lucas De Marchi wrote:
>On Tue, Oct 29, 2024 at 10:27:28AM -0700, Umesh Nerlige Ramappa wrote:
>>On Mon, Oct 28, 2024 at 05:32:03PM -0500, Lucas De Marchi wrote:
>>>On Mon, Oct 28, 2024 at 01:33:09PM -0700, Umesh Nerlige Ramappa wrote:
>>>>On Sat, Oct 26, 2024 at 12:08:47PM -0500, Lucas De Marchi wrote:
>>>>>When the exec queue is destroyed, there's a race between a query to the
>>>>>fdinfo and the exec queue value being updated: after the destroy ioctl,
>>>>>if the fdinfo is queried before a call to guc_exec_queue_free_job(),
>>>>>the wrong utilization is reported: it's not accumulated on the query
>>>>>since the queue was removed from the array, and the value wasn't updated
>>>>>yet by the free_job().
>>>>>
>>>>>Explicitly accumulate the engine utilization so the right value is
>>>>>visible after the ioctl return.
>>>>>
>>>>>Link: https://gitlab.freedesktop.org/drm/xe/kernel/-/issues/2667
>>>>>Cc: Jonathan Cavitt <jonathan.cavitt@intel.com>
>>>>>Signed-off-by: Lucas De Marchi <lucas.demarchi@intel.com>
>>>>>---
>>>>>drivers/gpu/drm/xe/xe_exec_queue.c | 8 ++++++++
>>>>>1 file changed, 8 insertions(+)
>>>>>
>>>>>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>>>>>index d098d2dd1b2d..b15ca84b2422 100644
>>>>>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>>>>>++ b/drivers/gpu/drm/xe/xe_exec_quee.c
>>>>>@@ -829,6 +829,14 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>>>>>
>>>>>	xe_exec_queue_kill(q);
>>>>>
>>>>>+	/*
>>>>>+	 * After killing and destroying the exec queue, make sure userspace has
>>>>>+	 * an updated view of the run ticks, regardless if this was the last
>>>>>+	 * ref: since the exec queue is removed from xef->exec_queue.xa, a
>>>>>+	 * query to fdinfo after this returns could not account for this load.
>>>>>+	 */
>>>>>+	xe_exec_queue_update_run_ticks(q);
>>>>>+
>>>>
>>>>At this point we may/may-not have the updated LRC timestamp.
>>>>
>>>>fwiu, xe_exec_queue_kill() is an async call. It will queue a 
>>>>work that will disable guc scheduling on the context. Once guc 
>>>>notifies KMD that scheduling is disabled on this context, KMD 
>>>>knows for sure that the context has switched out and the lrc 
>>>>timestamp is updated for this
>>>
>>>ok. do you know what's that notification? Is it the cleanup that we
>>>process at __guc_exec_queue_process_msg_cleanup() ?  (which is where I'm
>>>moving the io read to in the other patch)
>>>
>>>>context. It may work well for contexts that switch frequently 
>>>>and may not work for contexts that seldom switch or never 
>>>>destroy their exec queue.
>>>
>>>why does it matter? it's only for contexts going away - for context that
>>>are scheduled out the sampling on fdinfo read covers it. Note that this
>>>call is not replacing other calls. If the exec queue is not destroyed,
>>>the other 2 places should still cover it.
>>>
>>>The problem with the case when the destroy ioctl is called is that q is
>>>removed from xef->exec_queue.xa, so the additional call in fdinfo-read stops
>>>working. It  then relies on the last job completing and being released before
>>>a read on the fdinfo. As CI shows, this is racy and fails in ~10% of
>>>the cases.
>>>
>>>On a remote system I got it was failing ~20% of the time
>>>
>>>>
>>>>I still believe calling it from job free is the right thing to 
>>>>do. As for the ~120 Hz updates, these are just memory updates, 
>>>>so not sure if it's a huge performance impact.
>>>
>>>it seems now you are commenting on the change in the other patch?
>>
>>sorry, I will try to be more clear here.
>>
>>patch 3/3:
>>
>>I missed the fact that the updates could be in VRAM, so moving the 
>>update out of job_free makes sense.
>>
>>Also since fdinfo query is expected to be frequent enough, adding 
>>the update to exec_queue_fini makes sense too.
>>
>>patch 2/3 (everything below)
>>
>>it's just the update in destroy_ioctl that I am not convinced about 
>>since the kill is async. Also you see another instance of failure 
>>already below.
>>
>>>
>>>I think it's pretty pointless to do the io access when nobody cares
>>>about that number. The user needs to be reading the fdinfo, probably
>>>through gputop or the like for the number to be meaningful. So why do we
>>>care about sampling it at a high frequency when nobody is looking? For
>>>real, non-CI use-cases it should be as good as before.  The difference
>>>is that instead of getting 120 updates of few cycles, we are getting
>>>just 1 with the amount of cycles that got used in the last sampling
>>>period.
>>>
>>>Looking at the traces we do get a few low-msec execution time for
>>>xe_lrc_update_timestamp(). Mind you, there's another race about updating
>>>u32 in xef in a non-atomic way and doing it that frequently just makes
>>>it more likely to happen. That still needs a separate fix.
>>>
>>>Goal of this series is to make this work:
>>>
>>>	$ for ((i=0; i < 100; i++)); do echo $i/100 >&2; if ! ./build/tests/xe_drm_fdinfo; then break; fi; done
>>>
>>>I was happy when sending this that it passed. But just double checking
>>>on another host, the issue is still there and I get this after 16
>>>iterations:
>>>
>>>Starting subtest: utilization-single-full-load-destroy-queue
>>>....
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: spinner ended (timestamp=4818209)
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 1: cycles 9637999, total_cycles 19272820538
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 2: cycles 9637999, total_cycles 19277703269
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: percent: 0.000000
>>>(xe_drm_fdinfo:5997) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:527:
>>>(xe_drm_fdinfo:5997) CRITICAL: Failed assertion: 95.0 < percent
>>>(xe_drm_fdinfo:5997) CRITICAL: error: 95.000000 >= 0.000000
>>>(xe_drm_fdinfo:5997) igt_core-INFO: Stack trace:
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #1 [check_results+0x204]
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #2 ../tests/intel/xe_drm_fdinfo.c:860 __igt_unique____real_main806()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #6 [_start+0x25]
>>>****  END  ****
>>>
>>>which makes me think it's probably related to the kill being async as
>>>you mentioned.
>>>
>>>I wonder if we should synchronize the call in the fdinfo read with the
>>>queues that are going away.
>>
>>Hmm, maybe.
>
>doing that it passes for me 62/100 running all
>xe_drm_fdinfo@utilization-* tests.
>
>The failure on run 63 is different  and I think it's another bug or
>race. This is what I'm testing with currently:
>
>diff --git a/drivers/gpu/drm/xe/xe_device_types.h b/drivers/gpu/drm/xe/xe_device_types.h
>index a3e777ad281e3..eaee19efeadce 100644
>--- a/drivers/gpu/drm/xe/xe_device_types.h
>+++ b/drivers/gpu/drm/xe/xe_device_types.h
>@@ -614,6 +614,11 @@ struct xe_file {
>                 * does things while being held.
>                 */
>                struct mutex lock;
>+               /**
>+                * @exec_queue.pending_removal: items pending to be removed to
>+                * synchronize GPU state update with ongoing query.
>+                */
>+               atomic_t pending_removal;
>        } exec_queue;
>        /** @run_ticks: hw engine class run time in ticks for this drm client */
>diff --git a/drivers/gpu/drm/xe/xe_drm_client.c b/drivers/gpu/drm/xe/xe_drm_client.c
>index a9b0d640b2581..5f6347d12eec5 100644
>--- a/drivers/gpu/drm/xe/xe_drm_client.c
>+++ b/drivers/gpu/drm/xe/xe_drm_client.c
>@@ -327,6 +327,13 @@ static void show_run_ticks(struct drm_printer *p, struct drm_file *file)
>        if (!read_total_gpu_timestamp(xe, &gpu_timestamp))
>                goto fail_gpu_timestamp;
>+       /*
>+        * Wait for any exec queue going away: their cycles will get updated on
>+        * context switch out, so wait for that to happen
>+        */
>+        wait_var_event(&xef->exec_queue.pending_removal,
>+                       !atomic_read(&xef->exec_queue.pending_removal));
>+
>        xe_pm_runtime_put(xe);
>        for (class = 0; class < XE_ENGINE_CLASS_MAX; class++) {
>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>index fd0f3b3c9101d..58dd35beb15ad 100644
>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
>@@ -262,8 +262,11 @@ void xe_exec_queue_fini(struct xe_exec_queue *q)
>        /*
>         * Before releasing our ref to lrc and xef, accumulate our run ticks
>+        * and wakeup any waiters.
>         */
>        xe_exec_queue_update_run_ticks(q);
>+       if (q->xef && atomic_dec_and_test(&q->xef->exec_queue.pending_removal))
>+               wake_up_var(&q->xef->exec_queue.pending_removal);
>        for (i = 0; i < q->width; ++i)
>                xe_lrc_put(q->lrc[i]);
>@@ -824,6 +827,7 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>            XE_IOCTL_DBG(xe, args->reserved[0] || args->reserved[1]))
>                return -EINVAL;
>+       atomic_inc(&xef->exec_queue.pending_removal);
>        mutex_lock(&xef->exec_queue.lock);
>        q = xa_erase(&xef->exec_queue.xa, args->exec_queue_id);
>        mutex_unlock(&xef->exec_queue.lock);
>
>
>Idea is that any process reading the fdinfo needs to wait on contexts
>going away via kill.
>

Yep. That should work for the synchronization.

Once you kick off the queue destruction, it could be a small while 
before the context is actually stopped by GuC, so run ticks will keep 
ticking until then, but you may have sampled gt_timestamp already. Maybe 
sample the gt timestamp after the wait is over... just thinking out 
loud.

Thanks,
Umesh

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Lucas De Marchi]

On Tue, Oct 29, 2024 at 12:58:35PM -0500, Lucas De Marchi wrote:
>>>Starting subtest: utilization-single-full-load-destroy-queue
>>>....
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: spinner ended (timestamp=4818209)
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 1: cycles 9637999, total_cycles 19272820538
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 2: cycles 9637999, total_cycles 19277703269
>>>(xe_drm_fdinfo:5997) DEBUG: vcs: percent: 0.000000
>>>(xe_drm_fdinfo:5997) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:527:
>>>(xe_drm_fdinfo:5997) CRITICAL: Failed assertion: 95.0 < percent
>>>(xe_drm_fdinfo:5997) CRITICAL: error: 95.000000 >= 0.000000
>>>(xe_drm_fdinfo:5997) igt_core-INFO: Stack trace:
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #1 [check_results+0x204]
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #2 ../tests/intel/xe_drm_fdinfo.c:860 __igt_unique____real_main806()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #6 [_start+0x25]
>>>****  END  ****
>>>
>>>which makes me think it's probably related to the kill being async as
>>>you mentioned.
>>>
>>>I wonder if we should synchronize the call in the fdinfo read with the
>>>queues that are going away.
>>
>>Hmm, maybe.
>
>doing that it passes for me 62/100 running all
>xe_drm_fdinfo@utilization-* tests.
>
>The failure on run 63 is different  and I think it's another bug or


so the other failure, that I forgot to paste:

	Starting subtest: utilization-all-full-load
	(xe_drm_fdinfo:14864) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:528:
	(xe_drm_fdinfo:14864) CRITICAL: Failed assertion: percent < 105.0
	(xe_drm_fdinfo:14864) CRITICAL: error: 315.453826 >= 105.000000
	Stack trace:
	  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
	  #1 ../tests/intel/xe_drm_fdinfo.c:520 check_results()
	  #2 ../tests/intel/xe_drm_fdinfo.c:464 __igt_unique____real_main806()
	  #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
	  #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
	  #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
	  #6 [_start+0x25]
	Subtest utilization-all-full-load failed.
	**** DEBUG ****
	(xe_drm_fdinfo:14864) DEBUG: rcs: spinner started
	(xe_drm_fdinfo:14864) DEBUG: bcs: spinner started
	(xe_drm_fdinfo:14864) DEBUG: ccs: spinner started
	(xe_drm_fdinfo:14864) DEBUG: vcs: spinner started
	(xe_drm_fdinfo:14864) DEBUG: vecs: spinner started
	(xe_drm_fdinfo:14864) DEBUG: rcs: spinner ended (timestamp=15218479)
	(xe_drm_fdinfo:14864) DEBUG: bcs: spinner ended (timestamp=15194339)
	(xe_drm_fdinfo:14864) DEBUG: vcs: spinner ended (timestamp=4837648)
	(xe_drm_fdinfo:14864) DEBUG: vecs: spinner ended (timestamp=4816316)
	(xe_drm_fdinfo:14864) DEBUG: ccs: spinner ended (timestamp=4859494)
	(xe_drm_fdinfo:14864) DEBUG: rcs: sample 1: cycles 40481368, total_cycles 31104224861
	(xe_drm_fdinfo:14864) DEBUG: rcs: sample 2: cycles 55700053, total_cycles 31109049238
	(xe_drm_fdinfo:14864) DEBUG: rcs: percent: 315.453826
	(xe_drm_fdinfo:14864) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:528:
	(xe_drm_fdinfo:14864) CRITICAL: Failed assertion: percent < 105.0
	(xe_drm_fdinfo:14864) CRITICAL: error: 315.453826 >= 105.000000
	(xe_drm_fdinfo:14864) igt_core-INFO: Stack trace:
	(xe_drm_fdinfo:14864) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()


 From the timestamp read by the GPU;
rcs timestamp=15218479 and bcs timestamp=15194339... which is indeed much
higher than the total_cycles available:
31109049238 - 31104224861 = 4824377, which is reasonably similar to the
timestamp for the other engines.

my hypothesis is something like this:

sample1:
	accumulate_exec_queue (t = 0)
				<<<<<<<< premption
	read_total_gpu_cycles (t = 200)

sample2:
	accumulate_exec_queue (t = 300)
	read_total_gpu_cycles  (t = 300)


which makes cycles = 300, total_cycles = 200.

One easy thing to help: move the force wake finding/getting to the
beginning. I don't think it will be 100% bullet proof, but it improved
the execution on a misbehaving LNL to 100/100 pass. Maybe I was lucky in
this run.

Other than that we may need to resort to keep a copy of the last stamp
reported, redoing it if nonsense comes out, or add some locking

Lucas De Marchi

>race. This is what I'm testing with currently:
>
>diff --git a/drivers/gpu/drm/xe/xe_device_types.h b/drivers/gpu/drm/xe/xe_device_types.h
>index a3e777ad281e3..eaee19efeadce 100644
>--- a/drivers/gpu/drm/xe/xe_device_types.h
>+++ b/drivers/gpu/drm/xe/xe_device_types.h
>@@ -614,6 +614,11 @@ struct xe_file {
>                 * does things while being held.
>                 */
>                struct mutex lock;
>+               /**
>+                * @exec_queue.pending_removal: items pending to be removed to
>+                * synchronize GPU state update with ongoing query.
>+                */
>+               atomic_t pending_removal;
>        } exec_queue;
>        /** @run_ticks: hw engine class run time in ticks for this drm client */
>diff --git a/drivers/gpu/drm/xe/xe_drm_client.c b/drivers/gpu/drm/xe/xe_drm_client.c
>index a9b0d640b2581..5f6347d12eec5 100644
>--- a/drivers/gpu/drm/xe/xe_drm_client.c
>+++ b/drivers/gpu/drm/xe/xe_drm_client.c
>@@ -327,6 +327,13 @@ static void show_run_ticks(struct drm_printer *p, struct drm_file *file)
>        if (!read_total_gpu_timestamp(xe, &gpu_timestamp))
>                goto fail_gpu_timestamp;
>+       /*
>+        * Wait for any exec queue going away: their cycles will get updated on
>+        * context switch out, so wait for that to happen
>+        */
>+        wait_var_event(&xef->exec_queue.pending_removal,
>+                       !atomic_read(&xef->exec_queue.pending_removal));
>+
>        xe_pm_runtime_put(xe);
>        for (class = 0; class < XE_ENGINE_CLASS_MAX; class++) {
>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>index fd0f3b3c9101d..58dd35beb15ad 100644
>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
>@@ -262,8 +262,11 @@ void xe_exec_queue_fini(struct xe_exec_queue *q)
>        /*
>         * Before releasing our ref to lrc and xef, accumulate our run ticks
>+        * and wakeup any waiters.
>         */
>        xe_exec_queue_update_run_ticks(q);
>+       if (q->xef && atomic_dec_and_test(&q->xef->exec_queue.pending_removal))
>+               wake_up_var(&q->xef->exec_queue.pending_removal);
>        for (i = 0; i < q->width; ++i)
>                xe_lrc_put(q->lrc[i]);
>@@ -824,6 +827,7 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>            XE_IOCTL_DBG(xe, args->reserved[0] || args->reserved[1]))
>                return -EINVAL;
>+       atomic_inc(&xef->exec_queue.pending_removal);
>        mutex_lock(&xef->exec_queue.lock);
>        q = xa_erase(&xef->exec_queue.xa, args->exec_queue_id);
>        mutex_unlock(&xef->exec_queue.lock);
>
>
>Idea is that any process reading the fdinfo needs to wait on contexts
>going away via kill.
>
>
>>
>>I was of the opinion that we should solve it in Xe by adding an 
>>update call in an additional place (like you are doing), but after 
>>digging into it a bit, I am not sure if we should resolve this 
>>specific issue. Instead, we should alter the test to not check for 
>>accuracy when the queue is destroyed before taking the second 
>>sample. We know that the ticks will get updated at some reasonable 
>>point in future and the user will see it in subsequent fdinfo 
>>queries anyways. If that "reasonable point in future" is 
>>unacceptably large, then I think the problem is outside the PCEU 
>>domain.
>>
>>Note that the original reason we added the test was to catch the ref 
>>count issue with xef object (which is now fixed).
>>
>>>
>>>Another thought I had was to use the wabb, but afaics we can only
>>>execute something on context restore, not on context save.
>>
>>I am curious what you want to run in context save though and how 
>>it's any different from what's happening now - CTX_TIMESTAMP is 
>>being updated on save.
>
>I was thinking about letting the gpu use MI_MATH to keep calculating
>the delta.... but yeah, it wouldn't help in this particular case.
>
>
>>
>>>
>>>>
>>>>If the ftrace is getting filed up, we could throttle that.
>>>
>>>oh no, that is definitely not what I want. If we enable the tracepoint, we
>>>want to see it, not artifically drop the events.
>>>
>>>Initially (and to get a good measure of function runtime), I was
>>>actually using retsnoop rather than using the previously non-existent
>>>tracepoint:
>>>
>>>	retsnoop -e xe_lrc_update_timestamp -e xe_lrc_create -e xe_lrc_destroy  -S -A -C args.fmt-max-arg-width=0
>>
>>Didn't know that. That's ^ useful.
>
>life saver - I keep forgetting options for the other tools to do similar
>stuff, but this one is so simple and effective.
>
>Lucas De Marchi
>
>>
>>Thanks,
>>Umesh
>>>
>>>Lucas De Marchi
>>>
>>>>
>>>>Thanks,
>>>>Umesh
>>>>
>>>>>	trace_xe_exec_queue_close(q);
>>>>>	xe_exec_queue_put(q);
>>>>>
>>>>>-- 
>>>>>2.47.0
>>>>>

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Umesh Nerlige Ramappa]

On Tue, Oct 29, 2024 at 02:12:22PM -0500, Lucas De Marchi wrote:
>On Tue, Oct 29, 2024 at 12:58:35PM -0500, Lucas De Marchi wrote:
>>>>Starting subtest: utilization-single-full-load-destroy-queue
>>>>....
>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: spinner ended (timestamp=4818209)
>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 1: cycles 9637999, total_cycles 19272820538
>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 2: cycles 9637999, total_cycles 19277703269
>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: percent: 0.000000
>>>>(xe_drm_fdinfo:5997) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:527:
>>>>(xe_drm_fdinfo:5997) CRITICAL: Failed assertion: 95.0 < percent
>>>>(xe_drm_fdinfo:5997) CRITICAL: error: 95.000000 >= 0.000000
>>>>(xe_drm_fdinfo:5997) igt_core-INFO: Stack trace:
>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #1 [check_results+0x204]
>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #2 ../tests/intel/xe_drm_fdinfo.c:860 __igt_unique____real_main806()
>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #6 [_start+0x25]
>>>>****  END  ****
>>>>
>>>>which makes me think it's probably related to the kill being async as
>>>>you mentioned.
>>>>
>>>>I wonder if we should synchronize the call in the fdinfo read with the
>>>>queues that are going away.
>>>
>>>Hmm, maybe.
>>
>>doing that it passes for me 62/100 running all
>>xe_drm_fdinfo@utilization-* tests.
>>
>>The failure on run 63 is different  and I think it's another bug or
>
>
>so the other failure, that I forgot to paste:
>
>	Starting subtest: utilization-all-full-load
>	(xe_drm_fdinfo:14864) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:528:
>	(xe_drm_fdinfo:14864) CRITICAL: Failed assertion: percent < 105.0
>	(xe_drm_fdinfo:14864) CRITICAL: error: 315.453826 >= 105.000000
>	Stack trace:
>	  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>	  #1 ../tests/intel/xe_drm_fdinfo.c:520 check_results()
>	  #2 ../tests/intel/xe_drm_fdinfo.c:464 __igt_unique____real_main806()
>	  #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>	  #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>	  #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>	  #6 [_start+0x25]
>	Subtest utilization-all-full-load failed.
>	**** DEBUG ****
>	(xe_drm_fdinfo:14864) DEBUG: rcs: spinner started
>	(xe_drm_fdinfo:14864) DEBUG: bcs: spinner started
>	(xe_drm_fdinfo:14864) DEBUG: ccs: spinner started
>	(xe_drm_fdinfo:14864) DEBUG: vcs: spinner started
>	(xe_drm_fdinfo:14864) DEBUG: vecs: spinner started
>	(xe_drm_fdinfo:14864) DEBUG: rcs: spinner ended (timestamp=15218479)
>	(xe_drm_fdinfo:14864) DEBUG: bcs: spinner ended (timestamp=15194339)
>	(xe_drm_fdinfo:14864) DEBUG: vcs: spinner ended (timestamp=4837648)
>	(xe_drm_fdinfo:14864) DEBUG: vecs: spinner ended (timestamp=4816316)
>	(xe_drm_fdinfo:14864) DEBUG: ccs: spinner ended (timestamp=4859494)
>	(xe_drm_fdinfo:14864) DEBUG: rcs: sample 1: cycles 40481368, total_cycles 31104224861
>	(xe_drm_fdinfo:14864) DEBUG: rcs: sample 2: cycles 55700053, total_cycles 31109049238
>	(xe_drm_fdinfo:14864) DEBUG: rcs: percent: 315.453826
>	(xe_drm_fdinfo:14864) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:528:
>	(xe_drm_fdinfo:14864) CRITICAL: Failed assertion: percent < 105.0
>	(xe_drm_fdinfo:14864) CRITICAL: error: 315.453826 >= 105.000000
>	(xe_drm_fdinfo:14864) igt_core-INFO: Stack trace:
>	(xe_drm_fdinfo:14864) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>
>
>From the timestamp read by the GPU;
>rcs timestamp=15218479 and bcs timestamp=15194339... which is indeed much
>higher than the total_cycles available:
>31109049238 - 31104224861 = 4824377, which is reasonably similar to the
>timestamp for the other engines.
>
>my hypothesis is something like this:
>
>sample1:
>	accumulate_exec_queue (t = 0)
>				<<<<<<<< premption
>	read_total_gpu_cycles (t = 200)
>
>sample2:
>	accumulate_exec_queue (t = 300)
>	read_total_gpu_cycles  (t = 300)
>

It could as well be the second sample, see my previous email on why run 
ticks can be larger than the gt timestamp delta.

For the sake of narrowing it down, you could capture the value of 
CTX_TIMESTAMP mmio before killing the exec queue in destroy. It should 
be ticking since the context is active. Once the context stops, it would 
have an updated value. That way we know how long it took to stop.

Thanks,
Umesh

>
>which makes cycles = 300, total_cycles = 200.
>
>One easy thing to help: move the force wake finding/getting to the
>beginning. I don't think it will be 100% bullet proof, but it improved
>the execution on a misbehaving LNL to 100/100 pass. Maybe I was lucky in
>this run.
>
>Other than that we may need to resort to keep a copy of the last stamp
>reported, redoing it if nonsense comes out, or add some locking
>
>Lucas De Marchi
>
>>race. This is what I'm testing with currently:
>>
>>diff --git a/drivers/gpu/drm/xe/xe_device_types.h b/drivers/gpu/drm/xe/xe_device_types.h
>>index a3e777ad281e3..eaee19efeadce 100644
>>--- a/drivers/gpu/drm/xe/xe_device_types.h
>>+++ b/drivers/gpu/drm/xe/xe_device_types.h
>>@@ -614,6 +614,11 @@ struct xe_file {
>>                * does things while being held.
>>                */
>>               struct mutex lock;
>>+               /**
>>+                * @exec_queue.pending_removal: items pending to be removed to
>>+                * synchronize GPU state update with ongoing query.
>>+                */
>>+               atomic_t pending_removal;
>>       } exec_queue;
>>       /** @run_ticks: hw engine class run time in ticks for this drm client */
>>diff --git a/drivers/gpu/drm/xe/xe_drm_client.c b/drivers/gpu/drm/xe/xe_drm_client.c
>>index a9b0d640b2581..5f6347d12eec5 100644
>>--- a/drivers/gpu/drm/xe/xe_drm_client.c
>>+++ b/drivers/gpu/drm/xe/xe_drm_client.c
>>@@ -327,6 +327,13 @@ static void show_run_ticks(struct drm_printer *p, struct drm_file *file)
>>       if (!read_total_gpu_timestamp(xe, &gpu_timestamp))
>>               goto fail_gpu_timestamp;
>>+       /*
>>+        * Wait for any exec queue going away: their cycles will get updated on
>>+        * context switch out, so wait for that to happen
>>+        */
>>+        wait_var_event(&xef->exec_queue.pending_removal,
>>+                       !atomic_read(&xef->exec_queue.pending_removal));
>>+
>>       xe_pm_runtime_put(xe);
>>       for (class = 0; class < XE_ENGINE_CLASS_MAX; class++) {
>>diff --git a/drivers/gpu/drm/xe/xe_exec_queue.c b/drivers/gpu/drm/xe/xe_exec_queue.c
>>index fd0f3b3c9101d..58dd35beb15ad 100644
>>--- a/drivers/gpu/drm/xe/xe_exec_queue.c
>>+++ b/drivers/gpu/drm/xe/xe_exec_queue.c
>>@@ -262,8 +262,11 @@ void xe_exec_queue_fini(struct xe_exec_queue *q)
>>       /*
>>        * Before releasing our ref to lrc and xef, accumulate our run ticks
>>+        * and wakeup any waiters.
>>        */
>>       xe_exec_queue_update_run_ticks(q);
>>+       if (q->xef && atomic_dec_and_test(&q->xef->exec_queue.pending_removal))
>>+               wake_up_var(&q->xef->exec_queue.pending_removal);
>>       for (i = 0; i < q->width; ++i)
>>               xe_lrc_put(q->lrc[i]);
>>@@ -824,6 +827,7 @@ int xe_exec_queue_destroy_ioctl(struct drm_device *dev, void *data,
>>           XE_IOCTL_DBG(xe, args->reserved[0] || args->reserved[1]))
>>               return -EINVAL;
>>+       atomic_inc(&xef->exec_queue.pending_removal);
>>       mutex_lock(&xef->exec_queue.lock);
>>       q = xa_erase(&xef->exec_queue.xa, args->exec_queue_id);
>>       mutex_unlock(&xef->exec_queue.lock);
>>
>>
>>Idea is that any process reading the fdinfo needs to wait on contexts
>>going away via kill.
>>
>>
>>>
>>>I was of the opinion that we should solve it in Xe by adding an 
>>>update call in an additional place (like you are doing), but after 
>>>digging into it a bit, I am not sure if we should resolve this 
>>>specific issue. Instead, we should alter the test to not check for 
>>>accuracy when the queue is destroyed before taking the second 
>>>sample. We know that the ticks will get updated at some reasonable 
>>>point in future and the user will see it in subsequent fdinfo 
>>>queries anyways. If that "reasonable point in future" is 
>>>unacceptably large, then I think the problem is outside the PCEU 
>>>domain.
>>>
>>>Note that the original reason we added the test was to catch the 
>>>ref count issue with xef object (which is now fixed).
>>>
>>>>
>>>>Another thought I had was to use the wabb, but afaics we can only
>>>>execute something on context restore, not on context save.
>>>
>>>I am curious what you want to run in context save though and how 
>>>it's any different from what's happening now - CTX_TIMESTAMP is 
>>>being updated on save.
>>
>>I was thinking about letting the gpu use MI_MATH to keep calculating
>>the delta.... but yeah, it wouldn't help in this particular case.
>>
>>
>>>
>>>>
>>>>>
>>>>>If the ftrace is getting filed up, we could throttle that.
>>>>
>>>>oh no, that is definitely not what I want. If we enable the tracepoint, we
>>>>want to see it, not artifically drop the events.
>>>>
>>>>Initially (and to get a good measure of function runtime), I was
>>>>actually using retsnoop rather than using the previously non-existent
>>>>tracepoint:
>>>>
>>>>	retsnoop -e xe_lrc_update_timestamp -e xe_lrc_create -e xe_lrc_destroy  -S -A -C args.fmt-max-arg-width=0
>>>
>>>Didn't know that. That's ^ useful.
>>
>>life saver - I keep forgetting options for the other tools to do similar
>>stuff, but this one is so simple and effective.
>>
>>Lucas De Marchi
>>
>>>
>>>Thanks,
>>>Umesh
>>>>
>>>>Lucas De Marchi
>>>>
>>>>>
>>>>>Thanks,
>>>>>Umesh
>>>>>
>>>>>>	trace_xe_exec_queue_close(q);
>>>>>>	xe_exec_queue_put(q);
>>>>>>
>>>>>>-- 
>>>>>>2.47.0
>>>>>>

Re: [PATCH 2/3] drm/xe: Accumulate exec queue timestamp on destroy

[Lucas De Marchi]

On Tue, Oct 29, 2024 at 12:31:54PM -0700, Umesh Nerlige Ramappa wrote:
>On Tue, Oct 29, 2024 at 02:12:22PM -0500, Lucas De Marchi wrote:
>>On Tue, Oct 29, 2024 at 12:58:35PM -0500, Lucas De Marchi wrote:
>>>>>Starting subtest: utilization-single-full-load-destroy-queue
>>>>>....
>>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: spinner ended (timestamp=4818209)
>>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 1: cycles 9637999, total_cycles 19272820538
>>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: sample 2: cycles 9637999, total_cycles 19277703269
>>>>>(xe_drm_fdinfo:5997) DEBUG: vcs: percent: 0.000000
>>>>>(xe_drm_fdinfo:5997) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:527:
>>>>>(xe_drm_fdinfo:5997) CRITICAL: Failed assertion: 95.0 < percent
>>>>>(xe_drm_fdinfo:5997) CRITICAL: error: 95.000000 >= 0.000000
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO: Stack trace:
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #1 [check_results+0x204]
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #2 ../tests/intel/xe_drm_fdinfo.c:860 __igt_unique____real_main806()
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>>>>>(xe_drm_fdinfo:5997) igt_core-INFO:   #6 [_start+0x25]
>>>>>****  END  ****
>>>>>
>>>>>which makes me think it's probably related to the kill being async as
>>>>>you mentioned.
>>>>>
>>>>>I wonder if we should synchronize the call in the fdinfo read with the
>>>>>queues that are going away.
>>>>
>>>>Hmm, maybe.
>>>
>>>doing that it passes for me 62/100 running all
>>>xe_drm_fdinfo@utilization-* tests.
>>>
>>>The failure on run 63 is different  and I think it's another bug or
>>
>>
>>so the other failure, that I forgot to paste:
>>
>>	Starting subtest: utilization-all-full-load
>>	(xe_drm_fdinfo:14864) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:528:
>>	(xe_drm_fdinfo:14864) CRITICAL: Failed assertion: percent < 105.0
>>	(xe_drm_fdinfo:14864) CRITICAL: error: 315.453826 >= 105.000000
>>	Stack trace:
>>	  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>>	  #1 ../tests/intel/xe_drm_fdinfo.c:520 check_results()
>>	  #2 ../tests/intel/xe_drm_fdinfo.c:464 __igt_unique____real_main806()
>>	  #3 ../tests/intel/xe_drm_fdinfo.c:806 main()
>>	  #4 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
>>	  #5 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
>>	  #6 [_start+0x25]
>>	Subtest utilization-all-full-load failed.
>>	**** DEBUG ****
>>	(xe_drm_fdinfo:14864) DEBUG: rcs: spinner started
>>	(xe_drm_fdinfo:14864) DEBUG: bcs: spinner started
>>	(xe_drm_fdinfo:14864) DEBUG: ccs: spinner started
>>	(xe_drm_fdinfo:14864) DEBUG: vcs: spinner started
>>	(xe_drm_fdinfo:14864) DEBUG: vecs: spinner started
>>	(xe_drm_fdinfo:14864) DEBUG: rcs: spinner ended (timestamp=15218479)
>>	(xe_drm_fdinfo:14864) DEBUG: bcs: spinner ended (timestamp=15194339)
>>	(xe_drm_fdinfo:14864) DEBUG: vcs: spinner ended (timestamp=4837648)
>>	(xe_drm_fdinfo:14864) DEBUG: vecs: spinner ended (timestamp=4816316)
>>	(xe_drm_fdinfo:14864) DEBUG: ccs: spinner ended (timestamp=4859494)
>>	(xe_drm_fdinfo:14864) DEBUG: rcs: sample 1: cycles 40481368, total_cycles 31104224861
>>	(xe_drm_fdinfo:14864) DEBUG: rcs: sample 2: cycles 55700053, total_cycles 31109049238
>>	(xe_drm_fdinfo:14864) DEBUG: rcs: percent: 315.453826
>>	(xe_drm_fdinfo:14864) CRITICAL: Test assertion failure function check_results, file ../tests/intel/xe_drm_fdinfo.c:528:
>>	(xe_drm_fdinfo:14864) CRITICAL: Failed assertion: percent < 105.0
>>	(xe_drm_fdinfo:14864) CRITICAL: error: 315.453826 >= 105.000000
>>	(xe_drm_fdinfo:14864) igt_core-INFO: Stack trace:
>>	(xe_drm_fdinfo:14864) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
>>
>>
>>From the timestamp read by the GPU;
>>rcs timestamp=15218479 and bcs timestamp=15194339... which is indeed much
>>higher than the total_cycles available:
>>31109049238 - 31104224861 = 4824377, which is reasonably similar to the
>>timestamp for the other engines.
>>
>>my hypothesis is something like this:
>>
>>sample1:
>>	accumulate_exec_queue (t = 0)
>>				<<<<<<<< premption
>>	read_total_gpu_cycles (t = 200)
>>
>>sample2:
>>	accumulate_exec_queue (t = 300)
>>	read_total_gpu_cycles  (t = 300)
>>
>
>It could as well be the second sample, see my previous email on why 
>run ticks can be larger than the gt timestamp delta.
>
>For the sake of narrowing it down, you could capture the value of 
>CTX_TIMESTAMP mmio before killing the exec queue in destroy. It should 
>be ticking since the context is active. Once the context stops, it 
>would have an updated value. That way we know how long it took to 
>stop.

in this test there is no kill involved.... it happens in
utilization-all-full-load

Lucas De Marchi