[PATCH v4 30/38] drm/i915: Added scheduler statistic reporting to debugfs

John.C.Harrison
2016-01-11T18:43:41Z

It is useful for know what the scheduler is doing for both debugging
and performance analysis purposes. This change adds a bunch of
counters and such that keep track of various scheduler operations
(batches submitted, completed, flush requests, etc.). The data can
then be read in userland via the debugfs mechanism.

v2: Updated to match changes to scheduler implementation.

v3: Updated for changes to kill code and flush code.

v4: Removed the fence/sync code as that will be part of a separate
patch series. Wrapped a long line to keep the style checker happy.

For: VIZ-1587
Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
---
drivers/gpu/drm/i915/i915_debugfs.c | 73 ++++++++++++++++++++++++++++++
drivers/gpu/drm/i915/i915_gem_execbuffer.c | 2 +
drivers/gpu/drm/i915/i915_scheduler.c | 70 ++++++++++++++++++++++++++--
drivers/gpu/drm/i915/i915_scheduler.h | 31 +++++++++++++
4 files changed, 171 insertions(+), 5 deletions(-)

diff --git a/drivers/gpu/drm/i915/i915_debugfs.c b/drivers/gpu/drm/i915/i915_debugfs.c
index 611e691..73d0f97 100644
--- a/drivers/gpu/drm/i915/i915_debugfs.c
+++ b/drivers/gpu/drm/i915/i915_debugfs.c
@@ -3602,6 +3602,78 @@ static int i915_drrs_status(struct seq_file *m, void *unused)
return 0;
}

+static int i915_scheduler_info(struct seq_file *m, void *unused)
+{
+ struct drm_info_node *node = (struct drm_info_node *) m->private;
+ struct drm_device *dev = node->minor->dev;
+ struct drm_i915_private *dev_priv = dev->dev_private;
+ struct i915_scheduler *scheduler = dev_priv->scheduler;
+ struct i915_scheduler_stats *stats = scheduler->stats;
+ struct i915_scheduler_stats_nodes node_stats[I915_NUM_RINGS];
+ struct intel_engine_cs *ring;
+ char str[50 * (I915_NUM_RINGS + 1)], name[50], *ptr;
+ int ret, i, r;
+
+ ret = mutex_lock_interruptible(&dev->mode_config.mutex);
+ if (ret)
+ return ret;
+
+#define PRINT_VAR(name, fmt, var) \
+ do { \
+ sprintf(str, "%-22s", name); \
+ ptr = str + strlen(str); \
+ for_each_ring(ring, dev_priv, r) { \
+ sprintf(ptr, " %10" fmt, var); \
+ ptr += strlen(ptr); \
+ } \
+ seq_printf(m, "%s\n", str); \
+ } while (0)
+
+ PRINT_VAR("Ring name:", "s", dev_priv->ring[r].name);
+ PRINT_VAR(" Ring seqno", "d", ring->get_seqno(ring, false));
+ seq_putc(m, '\n');
+
+ seq_puts(m, "Batch submissions:\n");
+ PRINT_VAR(" Queued", "u", stats[r].queued);
+ PRINT_VAR(" Submitted", "u", stats[r].submitted);
+ PRINT_VAR(" Completed", "u", stats[r].completed);
+ PRINT_VAR(" Expired", "u", stats[r].expired);
+ seq_putc(m, '\n');
+
+ seq_puts(m, "Flush counts:\n");
+ PRINT_VAR(" By object", "u", stats[r].flush_obj);
+ PRINT_VAR(" By request", "u", stats[r].flush_req);
+ PRINT_VAR(" By stamp", "u", stats[r].flush_stamp);
+ PRINT_VAR(" Blanket", "u", stats[r].flush_all);
+ PRINT_VAR(" Entries bumped", "u", stats[r].flush_bump);
+ PRINT_VAR(" Entries submitted", "u", stats[r].flush_submit);
+ seq_putc(m, '\n');
+
+ seq_puts(m, "Miscellaneous:\n");
+ PRINT_VAR(" ExecEarly retry", "u", stats[r].exec_early);
+ PRINT_VAR(" ExecFinal requeue", "u", stats[r].exec_again);
+ PRINT_VAR(" ExecFinal killed", "u", stats[r].exec_dead);
+ PRINT_VAR(" Hung flying", "u", stats[r].kill_flying);
+ PRINT_VAR(" Hung queued", "u", stats[r].kill_queued);
+ seq_putc(m, '\n');
+
+ seq_puts(m, "Queue contents:\n");
+ for_each_ring(ring, dev_priv, i)
+ i915_scheduler_query_stats(ring, node_stats + ring->id);
+
+ for (i = 0; i < (i915_sqs_MAX + 1); i++) {
+ sprintf(name, " %s", i915_scheduler_queue_status_str(i));
+ PRINT_VAR(name, "d", node_stats[r].counts[i]);
+ }
+ seq_putc(m, '\n');
+
+#undef PRINT_VAR
+
+ mutex_unlock(&dev->mode_config.mutex);
+
+ return 0;
+}
+
struct pipe_crc_info {
const char *name;
struct drm_device *dev;
@@ -5570,6 +5642,7 @@ static const struct drm_info_list i915_debugfs_list[] = {
{"i915_semaphore_status", i915_semaphore_status, 0},
{"i915_shared_dplls_info", i915_shared_dplls_info, 0},
{"i915_dp_mst_info", i915_dp_mst_info, 0},
+ {"i915_scheduler_info", i915_scheduler_info, 0},
{"i915_wa_registers", i915_wa_registers, 0},
{"i915_ddb_info", i915_ddb_info, 0},
{"i915_sseu_status", i915_sseu_status, 0},
diff --git a/drivers/gpu/drm/i915/i915_gem_execbuffer.c b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
index 6336479..a752b7f 100644
--- a/drivers/gpu/drm/i915/i915_gem_execbuffer.c
+++ b/drivers/gpu/drm/i915/i915_gem_execbuffer.c
@@ -1743,6 +1743,8 @@ err:
mutex_unlock(&dev->struct_mutex);

pre_mutex_err:
+ dev_priv->scheduler->stats[ring->id].exec_early++;
+
return ret;
}

diff --git a/drivers/gpu/drm/i915/i915_scheduler.c b/drivers/gpu/drm/i915/i915_scheduler.c
index 2b4b74f..666e142 100644
--- a/drivers/gpu/drm/i915/i915_scheduler.c
+++ b/drivers/gpu/drm/i915/i915_scheduler.c
@@ -121,6 +121,9 @@ const char *i915_scheduler_queue_status_str(
case i915_sqs_dead:
return "Dead";

+ case i915_sqs_MAX:
+ return "Invalid";
+
default:
break;
}
@@ -267,12 +270,15 @@ int i915_scheduler_queue_execbuffer(struct i915_scheduler_queue_entry *qe)
if (i915.scheduler_override & i915_so_direct_submit) {
int ret;

+ scheduler->stats[qe->params.ring->id].queued++;
+
trace_i915_scheduler_queue(qe->params.ring, qe);

intel_ring_reserved_space_cancel(qe->params.request->ringbuf);

scheduler->flags[qe->params.ring->id] |= i915_sf_submitting;
ret = dev_priv->gt.execbuf_final(&qe->params);
+ scheduler->stats[qe->params.ring->id].submitted++;
scheduler->flags[qe->params.ring->id] &= ~i915_sf_submitting;

/*
@@ -303,6 +309,8 @@ int i915_scheduler_queue_execbuffer(struct i915_scheduler_queue_entry *qe)
if (qe->params.dispatch_flags & I915_DISPATCH_SECURE)
i915_gem_execbuff_release_batch_obj(qe->params.batch_obj);

+ scheduler->stats[qe->params.ring->id].expired++;
+
return 0;
}

@@ -386,6 +394,8 @@ int i915_scheduler_queue_execbuffer(struct i915_scheduler_queue_entry *qe)
not_flying = i915_scheduler_count_flying(scheduler, ring) <
scheduler->min_flying;

+ scheduler->stats[ring->id].queued++;
+
trace_i915_scheduler_queue(ring, node);
trace_i915_scheduler_node_state_change(ring, node);

@@ -497,13 +507,17 @@ static void i915_scheduler_node_requeue(struct i915_scheduler_queue_entry *node)
* Give up on a node completely. For example, because it is causing the
* ring to hang or is using some resource that no longer exists.
*/
-static void i915_scheduler_node_kill(struct i915_scheduler_queue_entry *node)
+static void i915_scheduler_node_kill(struct i915_scheduler *scheduler,
+ struct i915_scheduler_queue_entry *node)
{
WARN_ON(!node);
WARN_ON(I915_SQS_IS_COMPLETE(node));

- if (I915_SQS_IS_FLYING(node))
+ if (I915_SQS_IS_FLYING(node)) {
trace_i915_scheduler_unfly(node->params.ring, node);
+ scheduler->stats[node->params.ring->id].kill_flying++;
+ } else
+ scheduler->stats[node->params.ring->id].kill_queued++;

node->status = i915_sqs_dead;
trace_i915_scheduler_node_state_change(node->params.ring, node);
@@ -536,10 +550,13 @@ bool i915_scheduler_notify_request(struct drm_i915_gem_request *req)
WARN_ON(!I915_SQS_IS_FLYING(node));

/* Node was in flight so mark it as complete. */
- if (req->cancelled)
+ if (req->cancelled) {
node->status = i915_sqs_dead;
- else
+ scheduler->stats[req->ring->id].kill_flying++;
+ } else {
node->status = i915_sqs_complete;
+ scheduler->stats[req->ring->id].completed++;
+ }

trace_i915_scheduler_node_state_change(req->ring, node);

@@ -669,6 +686,7 @@ static int i915_scheduler_remove(struct intel_engine_cs *ring)

list_del(&node->link);
list_add(&node->link, &remove);
+ scheduler->stats[ring->id].expired++;

/* Strip the dependency info while the mutex is still locked */
i915_scheduler_remove_dependent(scheduler, node);
@@ -907,6 +925,36 @@ static int i915_scheduler_dump_locked(struct intel_engine_cs *ring,
return 0;
}

+int i915_scheduler_query_stats(struct intel_engine_cs *ring,
+ struct i915_scheduler_stats_nodes *stats)
+{
+ struct drm_i915_private *dev_priv = ring->dev->dev_private;
+ struct i915_scheduler *scheduler = dev_priv->scheduler;
+ struct i915_scheduler_queue_entry *node;
+ unsigned long flags;
+
+ memset(stats, 0x00, sizeof(*stats));
+
+ spin_lock_irqsave(&scheduler->lock, flags);
+
+ list_for_each_entry(node, &scheduler->node_queue[ring->id], link) {
+ if (node->status >= i915_sqs_MAX) {
+ DRM_DEBUG_DRIVER("Invalid node state: %d! [uniq = %d, seqno = %d]\n",
+ node->status, node->params.request->uniq,
+ node->params.request->seqno);
+
+ stats->counts[i915_sqs_MAX]++;
+ continue;
+ }
+
+ stats->counts[node->status]++;
+ }
+
+ spin_unlock_irqrestore(&scheduler->lock, flags);
+
+ return 0;
+}
+
int i915_scheduler_flush_stamp(struct intel_engine_cs *ring,
unsigned long target,
bool is_locked)
@@ -935,6 +983,7 @@ int i915_scheduler_flush_stamp(struct intel_engine_cs *ring,
}

spin_lock_irqsave(&scheduler->lock, flags);
+ scheduler->stats[ring->id].flush_stamp++;
i915_scheduler_priority_bump_clear(scheduler);
list_for_each_entry(node, &scheduler->node_queue[ring->id], link) {
if (!I915_SQS_IS_QUEUED(node))
@@ -945,12 +994,15 @@ int i915_scheduler_flush_stamp(struct intel_engine_cs *ring,

flush_count = i915_scheduler_priority_bump(scheduler,
node, scheduler->priority_level_max);
+ scheduler->stats[ring->id].flush_bump += flush_count;
}
spin_unlock_irqrestore(&scheduler->lock, flags);

if (flush_count) {
DRM_DEBUG_DRIVER("<%s> Bumped %d entries\n", ring->name, flush_count);
flush_count = i915_scheduler_submit_max_priority(ring, is_locked);
+ if (flush_count > 0)
+ scheduler->stats[ring->id].flush_submit += flush_count;
}

return flush_count;
@@ -977,6 +1029,8 @@ int i915_scheduler_flush(struct intel_engine_cs *ring, bool is_locked)

WARN_ON(is_locked && (scheduler->flags[ring->id] & i915_sf_submitting));

+ scheduler->stats[ring->id].flush_all++;
+
do {
found = false;
spin_lock_irqsave(&scheduler->lock, flags);
@@ -991,6 +1045,7 @@ int i915_scheduler_flush(struct intel_engine_cs *ring, bool is_locked)

if (found) {
ret = i915_scheduler_submit(ring, is_locked);
+ scheduler->stats[ring->id].flush_submit++;
if (ret < 0)
return ret;

@@ -1214,6 +1269,8 @@ static int i915_scheduler_submit(struct intel_engine_cs *ring, bool was_locked)
*/
i915_scheduler_fly_node(node);

+ scheduler->stats[ring->id].submitted++;
+
scheduler->flags[ring->id] |= i915_sf_submitting;
spin_unlock_irqrestore(&scheduler->lock, flags);
ret = dev_priv->gt.execbuf_final(&node->params);
@@ -1234,6 +1291,7 @@ static int i915_scheduler_submit(struct intel_engine_cs *ring, bool was_locked)
case ENOENT:
/* Fatal errors. Kill the node. */
requeue = -1;
+ scheduler->stats[ring->id].exec_dead++;
break;

case EAGAIN:
@@ -1243,6 +1301,7 @@ static int i915_scheduler_submit(struct intel_engine_cs *ring, bool was_locked)
case ERESTARTSYS:
case EINTR:
/* Supposedly recoverable errors. */
+ scheduler->stats[ring->id].exec_again++;
break;

default:
@@ -1252,6 +1311,7 @@ static int i915_scheduler_submit(struct intel_engine_cs *ring, bool was_locked)
*/
DRM_DEBUG_DRIVER("<%s> Got unexpected error from execfinal(): %d!\n",
ring->name, ret);
+ scheduler->stats[ring->id].exec_again++;
break;
}

@@ -1271,7 +1331,7 @@ static int i915_scheduler_submit(struct intel_engine_cs *ring, bool was_locked)
*/
break;
} else if (requeue == -1)
- i915_scheduler_node_kill(node);
+ i915_scheduler_node_kill(scheduler, node);
}

/* Keep launching until the sky is sufficiently full. */
diff --git a/drivers/gpu/drm/i915/i915_scheduler.h b/drivers/gpu/drm/i915/i915_scheduler.h
index 990f094..eff5d8f 100644
--- a/drivers/gpu/drm/i915/i915_scheduler.h
+++ b/drivers/gpu/drm/i915/i915_scheduler.h
@@ -70,6 +70,32 @@ struct i915_scheduler_queue_entry {
};
const char *i915_qe_state_str(struct i915_scheduler_queue_entry *node);

+struct i915_scheduler_stats_nodes {
+ uint32_t counts[i915_sqs_MAX + 1];
+};
+
+struct i915_scheduler_stats {
+ /* Batch buffer counts: */
+ uint32_t queued;
+ uint32_t submitted;
+ uint32_t completed;
+ uint32_t expired;
+
+ /* Other stuff: */
+ uint32_t flush_obj;
+ uint32_t flush_req;
+ uint32_t flush_stamp;
+ uint32_t flush_all;
+ uint32_t flush_bump;
+ uint32_t flush_submit;
+
+ uint32_t exec_early;
+ uint32_t exec_again;
+ uint32_t exec_dead;
+ uint32_t kill_flying;
+ uint32_t kill_queued;
+};
+
struct i915_scheduler {
struct list_head node_queue[I915_NUM_RINGS];
uint32_t flags[I915_NUM_RINGS];
@@ -81,6 +107,9 @@ struct i915_scheduler {
int32_t priority_level_preempt;
uint32_t min_flying;
uint32_t file_queue_max;
+
+ /* Statistics: */
+ struct i915_scheduler_stats stats[I915_NUM_RINGS];
};

/* Flag bits for i915_scheduler::flags */
@@ -119,6 +148,8 @@ int i915_scheduler_dump(struct intel_engine_cs *ring,
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);
+int i915_scheduler_query_stats(struct intel_engine_cs *ring,
+ struct i915_scheduler_stats_nodes *stats);
bool i915_scheduler_file_queue_is_full(struct drm_file *file);

#endif /* _I915_SCHEDULER_H_ */