Re: [PATCH v5 27/35] drm/i915: Added debug state dump facilities to scheduler

From: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
To: John.C.Harrison@Intel.com, Intel-GFX@Lists.FreeDesktop.Org
Subject: Re: [PATCH v5 27/35] drm/i915: Added debug state dump facilities to scheduler
Date: Mon, 07 Mar 2016 14:31:17 +0200	[thread overview]
Message-ID: <1457353877.14727.24.camel@linux.intel.com> (raw)
In-Reply-To: <1455805644-6450-28-git-send-email-John.C.Harrison@Intel.com>

Hi,

On to, 2016-02-18 at 14:27 +0000, John.C.Harrison@Intel.com wrote:
> From: John Harrison <John.C.Harrison@Intel.com>
> 
> When debugging batch buffer submission issues, it is useful to be able
> to see what the current state of the scheduler is. This change adds
> functions for decoding the internal scheduler state and reporting it.
> 
> v3: Updated a debug message with the new state_str() function.
> 
> v4: Wrapped some long lines to keep the style checker happy. Removed
> the fence/sync code as that will now be part of a separate patch series.
> 
> v5: Removed forward declarations and white space. Added documentation.
> [Joonas Lahtinen]
> 
> Also squashed in later patch to add seqno information from the start.
> It was only being added in a separate patch due to historical reasons
> which have since gone away.
> 
> For: VIZ-1587
> Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
> Cc: Joonas Lahtinen <joonas.lahtinen@linux.intel.com>
> ---
>  drivers/gpu/drm/i915/i915_scheduler.c | 302 +++++++++++++++++++++++++++++++++-
>  drivers/gpu/drm/i915/i915_scheduler.h |  15 ++
>  2 files changed, 315 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/gpu/drm/i915/i915_scheduler.c b/drivers/gpu/drm/i915/i915_scheduler.c
> index f7f29d5..d0eed52 100644
> --- a/drivers/gpu/drm/i915/i915_scheduler.c
> +++ b/drivers/gpu/drm/i915/i915_scheduler.c
> @@ -40,6 +40,117 @@ bool i915_scheduler_is_enabled(struct drm_device *dev)
>  	return dev_priv->scheduler != NULL;
>  }
> 

These sort of functions should be in i915_debugfs.c, so that nobody
even thinks of using them for other purposes.

>  
> +const char *i915_qe_state_str(struct i915_scheduler_queue_entry *node)
> +{
> +	static char	str[50];
> +	char		*ptr = str;
> +
> +	*(ptr++) = node->bumped ? 'B' : '-',
> +	*(ptr++) = i915_gem_request_completed(node->params.request) ? 'C' : '-';
> +

Especially this kind of code needs to be in i915_debugfs.c. I'd
implement new code more along lines of i915_sseu_status(), but I see
this kind of code was previously merged.

> +	*ptr = 0;
> +
> +	return str;
> +}
> +
> +char i915_scheduler_queue_status_chr(enum i915_scheduler_queue_status status)
> +{
> +	switch (status) {
> +	case i915_sqs_none:
> +	return 'N';
> +
> +	case i915_sqs_queued:
> +	return 'Q';
> +
> +	case i915_sqs_popped:
> +	return 'X';
> +
> +	case i915_sqs_flying:
> +	return 'F';
> +
> +	case i915_sqs_complete:
> +	return 'C';
> +
> +	case i915_sqs_dead:
> +	return 'D';
> +
> +	default:
> +	break;
> +	}
> +

Bad indent.

> +	return '?';
> +}
> +
> +const char *i915_scheduler_queue_status_str(
> +				enum i915_scheduler_queue_status status)
> +{
> +	static char	str[50];
> +
> +	switch (status) {
> +	case i915_sqs_none:
> +	return "None";
> +
> +	case i915_sqs_queued:
> +	return "Queued";
> +
> +	case i915_sqs_popped:
> +	return "Popped";
> +
> +	case i915_sqs_flying:
> +	return "Flying";
> +
> +	case i915_sqs_complete:
> +	return "Complete";
> +
> +	case i915_sqs_dead:
> +	return "Dead";
> +
> +	default:
> +	break;
> +	}
> +
> +	sprintf(str, "[Unknown_%d!]", status);
> +	return str;
> +}
> +
> +const char *i915_scheduler_flag_str(uint32_t flags)
> +{
> +	static char str[100];
> +	char *ptr = str;
> +
> +	*ptr = 0;
> +
> +#define TEST_FLAG(flag, msg)						\
> +	do {								\
> +		if (flags & (flag)) {					\
> +			strcpy(ptr, msg);				\
> +			ptr += strlen(ptr);				\
> +			flags &= ~(flag);				\
> +		}							\
> +	} while (0)
> +
> +	TEST_FLAG(i915_sf_interrupts_enabled, "IntOn|");
> +	TEST_FLAG(i915_sf_submitting,         "Submitting|");
> +	TEST_FLAG(i915_sf_dump_force,         "DumpForce|");
> +	TEST_FLAG(i915_sf_dump_details,       "DumpDetails|");
> +	TEST_FLAG(i915_sf_dump_dependencies,  "DumpDeps|");
> +	TEST_FLAG(i915_sf_dump_seqno,         "DumpSeqno|");
> +
> +#undef TEST_FLAG
> +
> +	if (flags) {
> +		sprintf(ptr, "Unknown_0x%X!", flags);
> +		ptr += strlen(ptr);
> +	}
> +
> +	if (ptr == str)
> +		strcpy(str, "-");
> +	else
> +		ptr[-1] = 0;
> +
> +	return str;
> +};
> +
>  /**
>   * i915_scheduler_init - Initialise the scheduler.
>   * @dev: DRM device
> @@ -1024,6 +1135,193 @@ void i915_scheduler_work_handler(struct work_struct *work)
>  		i915_scheduler_process_work(ring);
>  }
>  
> +static int i915_scheduler_dump_locked(struct intel_engine_cs *ring,
> +				      const char *msg)
> +{
> +	struct drm_i915_private *dev_priv = ring->dev->dev_private;
> +	struct i915_scheduler *scheduler = dev_priv->scheduler;
> +	struct i915_scheduler_queue_entry *node;
> +	int flying = 0, queued = 0, complete = 0, other = 0;
> +	static int old_flying = -1, old_queued = -1, old_complete = -1;
> +	bool b_dump;
> +	char brkt[2] = { '<', '>' };
> +
> +	if (!ring)
> +		return -EINVAL;
> +
> +	list_for_each_entry(node, &scheduler->node_queue[ring->id], link) {
> +		if (I915_SQS_IS_QUEUED(node))
> +			queued++;
> +		else if (I915_SQS_IS_FLYING(node))
> +			flying++;
> +		else if (I915_SQS_IS_COMPLETE(node))
> +			complete++;
> +		else
> +			other++;
> +	}
> +
> +	b_dump = (flying != old_flying) ||
> +		 (queued != old_queued) ||
> +		 (complete != old_complete);
> +	if (scheduler->flags[ring->id] & i915_sf_dump_force) {
> +		if (!b_dump) {
> +			b_dump = true;
> +			brkt[0] = '{';
> +			brkt[1] = '}';
> +		}
> +
> +		scheduler->flags[ring->id] &= ~i915_sf_dump_force;
> +	}
> +
> +	if (b_dump) {
> +		old_flying   = flying;
> +		old_queued   = queued;
> +		old_complete = complete;
> +		DRM_DEBUG_DRIVER("<%s> Q:%02d, F:%02d, C:%02d, O:%02d, "
> +				 "Flags = %s, Next = %d:%d %c%s%c\n",
> +				 ring->name, queued, flying, complete, other,
> +				 i915_scheduler_flag_str(scheduler->flags[ring->id]),
> +				 dev_priv->request_uniq, dev_priv->next_seqno,
> +				 brkt[0], msg, brkt[1]);

Convert to debugfs, it's the de-facto.

> +	} else {
> +		/*DRM_DEBUG_DRIVER("<%s> Q:%02d, F:%02d, C:%02d, O:%02d"
> +				 ", Flags = %s, Next = %d:%d [%s]\n",
> +				 ring->name,
> +				 queued, flying, complete, other,
> +				 i915_scheduler_flag_str(scheduler->flags[ring->id]),
> +				 dev_priv->request_uniq, dev_priv->next_seqno, msg); */
> +

Dead code to be removed from patches.

> +		return 0;
> +	}
> +
> +	if (scheduler->flags[ring->id] & i915_sf_dump_seqno) {
> +		uint32_t seqno;
> +
> +		seqno = ring->get_seqno(ring, true);
> +
> +		DRM_DEBUG_DRIVER("<%s> Seqno = %d\n", ring->name, seqno);
> +	}
> +
> +	if (scheduler->flags[ring->id] & i915_sf_dump_details) {
> +		int i, deps;
> +		uint32_t count, counts[i915_sqs_MAX];
> +
> +		memset(counts, 0x00, sizeof(counts));
> +
> +		list_for_each_entry(node, &scheduler->node_queue[ring->id], link) {
> +			if (node->status < i915_sqs_MAX) {
> +				count = counts[node->status]++;
> +			} else {
> +				DRM_DEBUG_DRIVER("<%s>   Unknown status: %d!\n",
> +						 ring->name, node->status);
> +				count = -1;
> +			}
> +
> +			deps = 0;
> +			for (i = 0; i < node->num_deps; i++)
> +				if (i915_scheduler_is_dependency_valid(node, i))
> +					deps++;
> +
> +			DRM_DEBUG_DRIVER("<%s>   %c:%02d> uniq = %d, seqno"
> +					 " = %d/%s, deps = %d / %d, %s [pri = "
> +					 "%4d]\n", ring->name,
> +					 i915_scheduler_queue_status_chr(node->status),
> +					 count,
> +					 node->params.request->uniq,
> +					 node->params.request->seqno,
> +					 node->params.ring->name,
> +					 deps, node->num_deps,
> +					 i915_qe_state_str(node),
> +					 node->priority);
> +
> +			if ((scheduler->flags[ring->id] & i915_sf_dump_dependencies)
> +				== 0)
> +				continue;
> +
> +			for (i = 0; i < node->num_deps; i++)
> +				if (node->dep_list[i])
> +					DRM_DEBUG_DRIVER("<%s>       |-%c:"
> +						"%02d%c uniq = %d, seqno = %d/%s, %s [pri = %4d]\n",
> +						ring->name,
> +						i915_scheduler_queue_status_chr(node->dep_list[i]->status),
> +						i,
> +						i915_scheduler_is_dependency_valid(node, i)
> +							? '>' : '#',
> +						node->dep_list[i]->params.request->uniq,
> +						node->dep_list[i]->params.request->seqno,
> +						node->dep_list[i]->params.ring->name,
> +						i915_qe_state_str(node->dep_list[i]),
> +						node->dep_list[i]->priority);
> +		}
> +	}
> +
> +	return 0;
> +}
> +
> +/**
> + * i915_scheduler_dump - dump the scheduler's internal state to the debug log.
> + * @ring: Ring to dump info for
> + * @msg: A reason why it is being dumped
> + * For debugging purposes, it can be very useful to see the internal state of
> + * the scheduler for a given ring.
> + */
> +int i915_scheduler_dump(struct intel_engine_cs *ring, const char *msg)
> +{
> +	struct drm_i915_private *dev_priv = ring->dev->dev_private;
> +	struct i915_scheduler *scheduler = dev_priv->scheduler;
> +	unsigned long flags;
> +	int ret;
> +
> +	spin_lock_irqsave(&scheduler->lock, flags);
> +	ret = i915_scheduler_dump_locked(ring, msg);
> +	spin_unlock_irqrestore(&scheduler->lock, flags);
> +
> +	return ret;
> +}
> +

This kind of stuff especially should be static functions in
i915_debugfs.c. And then they don't need kerneldoc either, because we
expect no sane invidual to call them.

> +static int i915_scheduler_dump_all_locked(struct drm_device *dev,
> +					  const char *msg)
> +{
> +	struct drm_i915_private *dev_priv = dev->dev_private;
> +	struct i915_scheduler *scheduler = dev_priv->scheduler;
> +	struct intel_engine_cs *ring;
> +	int i, r, ret = 0;
> +
> +	for_each_ring(ring, dev_priv, i) {
> +		scheduler->flags[ring->id] |= i915_sf_dump_force   |
> +					      i915_sf_dump_details |
> +					      i915_sf_dump_seqno   |
> +					      i915_sf_dump_dependencies;

This looks really bad to me, invasive debugging. Rather to be carried
as function parameters in the debug functions, and they should be
uppercase enum in i915_debugfs.c too.

> +		r = i915_scheduler_dump_locked(ring, msg);
> +		if (ret == 0)
> +			ret = r;
> +	}
> +
> +	return ret;
> +}
> +
> +/**
> + * i915_scheduler_dump_all - dump the scheduler's internal state to the debug
> + * log.
> + * @dev: DRM device
> + * @msg: A reason why it is being dumped
> + * For debugging purposes, it can be very useful to see the internal state of
> + * the scheduler.
> + */
> +int i915_scheduler_dump_all(struct drm_device *dev, const char *msg)
> +{
> +	struct drm_i915_private *dev_priv = dev->dev_private;
> +	struct i915_scheduler *scheduler = dev_priv->scheduler;
> +	unsigned long flags;
> +	int ret;
> +
> +	spin_lock_irqsave(&scheduler->lock, flags);
> +	ret = i915_scheduler_dump_all_locked(dev, msg);
> +	spin_unlock_irqrestore(&scheduler->lock, flags);
> +
> +	return ret;
> +}
> +
>  static int i915_scheduler_submit_max_priority(struct intel_engine_cs *ring,
>  					      bool is_locked)
>  {
> @@ -1246,10 +1544,10 @@ int i915_scheduler_closefile(struct drm_device *dev, struct drm_file *file)
>  				continue;
>  
>  			if (!I915_SQS_IS_COMPLETE(node))
> -				DRM_DEBUG_DRIVER("Closing file handle with outstanding work: %d:%d/%d on %s\n",
> +				DRM_DEBUG_DRIVER("Closing file handle with outstanding work: %d:%d/%s on %s\n",
>  						 node->params.request->uniq,
>  						 node->params.request->seqno,
> -						 node->status,
> +						 i915_qe_state_str(node),

If the code is to be called from outside of i915_debugfs.c, it should
really be written in a more safe manner than static char, especially as
it is not much of an effort to make a table to index.

Regards, Joonas

>  						 ring->name);
>  
>  			i915_scheduler_file_queue_dec(node->params.file);
> diff --git a/drivers/gpu/drm/i915/i915_scheduler.h b/drivers/gpu/drm/i915/i915_scheduler.h
> index b78de12..a071ebb 100644
> --- a/drivers/gpu/drm/i915/i915_scheduler.h
> +++ b/drivers/gpu/drm/i915/i915_scheduler.h
> @@ -41,6 +41,9 @@ enum i915_scheduler_queue_status {
>  	/* Limit value for use with arrays/loops */
>  	i915_sqs_MAX
>  };
> +char i915_scheduler_queue_status_chr(enum i915_scheduler_queue_status status);
> +const char *i915_scheduler_queue_status_str(
> +				enum i915_scheduler_queue_status status);
>  
>  #define I915_SQS_IS_QUEUED(node)	(((node)->status == i915_sqs_queued))
>  #define I915_SQS_IS_FLYING(node)	(((node)->status == i915_sqs_flying))
> @@ -65,6 +68,7 @@ struct i915_scheduler_queue_entry {
>  	unsigned long                       stamp;
>  	struct list_head                    link;
>  };
> +const char *i915_qe_state_str(struct i915_scheduler_queue_entry *node);
>  
>  struct i915_scheduler {
>  	struct list_head    node_queue[I915_NUM_RINGS];
> @@ -82,9 +86,17 @@ struct i915_scheduler {
>  
>  /* Flag bits for i915_scheduler::flags */
>  enum {
> +	/* Internal state */
>  	i915_sf_interrupts_enabled  = (1 << 0),
>  	i915_sf_submitting          = (1 << 1),
> +
> +	/* Dump/debug flags */
> +	i915_sf_dump_force          = (1 << 8),
> +	i915_sf_dump_details        = (1 << 9),
> +	i915_sf_dump_dependencies   = (1 << 10),
> +	i915_sf_dump_seqno          = (1 << 11),
>  };
> +const char *i915_scheduler_flag_str(uint32_t flags);
>  
>  bool i915_scheduler_is_enabled(struct drm_device *dev);
>  int i915_scheduler_init(struct drm_device *dev);
> @@ -99,6 +111,9 @@ void i915_scheduler_work_handler(struct work_struct *work);
>  int i915_scheduler_flush(struct intel_engine_cs *ring, bool is_locked);
>  int i915_scheduler_flush_stamp(struct intel_engine_cs *ring,
>  			       unsigned long stamp, bool is_locked);
> +int i915_scheduler_dump(struct intel_engine_cs *ring,
> +			const char *msg);
> +int i915_scheduler_dump_all(struct drm_device *dev, const char *msg);
>  bool i915_scheduler_is_request_tracked(struct drm_i915_gem_request *req,
>  				       bool *completed, bool *busy);
>  bool i915_scheduler_file_queue_is_full(struct drm_file *file);
-- 
Joonas Lahtinen
Open Source Technology Center
Intel Corporation
_______________________________________________
Intel-gfx mailing list
Intel-gfx@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/intel-gfx