blktrace: fix accounting of partially completed requests

trace_block_rq_complete does not take into account that request can
be partially completed, so we can get the following incorrect output
of blkparser:

  C   R 232 + 240 [0]
  C   R 240 + 232 [0]
  C   R 248 + 224 [0]
  C   R 256 + 216 [0]

but should be:

  C   R 232 + 8 [0]
  C   R 240 + 8 [0]
  C   R 248 + 8 [0]
  C   R 256 + 8 [0]

Also, the whole output summary statistics of completed requests and
final throughput will be incorrect.

This patch takes into account real completion size of the request and
fixes wrong completion accounting.

Signed-off-by: Roman Pen <r.peniaev@gmail.com>
CC: Steven Rostedt <rostedt@goodmis.org>
CC: Frederic Weisbecker <fweisbec@gmail.com>
CC: Ingo Molnar <mingo@redhat.com>
CC: linux-kernel@vger.kernel.org
Cc: stable@kernel.org
Signed-off-by: Jens Axboe <axboe@fb.com>

diff --git a/block/blk-core.c b/block/blk-core.c
index 853f92749202cbfe5b252d557f667b7f970ac872..99e20cca37e1a74ad0b4f6b18a98685b6918c26c 100644 (file)
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -2354,7 +2354,7 @@ bool blk_update_request(struct request *req, int error, unsigned int nr_bytes)
        if (!req->bio)
                return false;
 
-       trace_block_rq_complete(req->q, req);
+       trace_block_rq_complete(req->q, req, nr_bytes);
 
        /*
         * For fs requests, rq is just carrier of independent bio's

diff --git a/block/blk-mq.c b/block/blk-mq.c
index 6468a715a0e43f5883d24b04e81aa8234dc5decc..01d8735db8d3e425c84bfa3694935bcd1301e277 100644 (file)
--- a/block/blk-mq.c
+++ b/block/blk-mq.c
@@ -309,7 +309,7 @@ void blk_mq_end_io(struct request *rq, int error)
        struct bio *bio = rq->bio;
        unsigned int bytes = 0;
 
-       trace_block_rq_complete(rq->q, rq);
+       trace_block_rq_complete(rq->q, rq, blk_rq_bytes(rq));
 
        while (bio) {
                struct bio *next = bio->bi_next;

diff --git a/include/trace/events/block.h b/include/trace/events/block.h
index e76ae19a8d6fe65705e48104bb8212ed8bddb546..e8a5eca1dbe5787be56b31a317b0b6ac9b421a8e 100644 (file)
--- a/include/trace/events/block.h
+++ b/include/trace/events/block.h
@@ -132,6 +132,7 @@ DEFINE_EVENT(block_rq_with_error, block_rq_requeue,
  * block_rq_complete - block IO operation completed by device driver
  * @q: queue containing the block operation request
  * @rq: block operations request
+ * @nr_bytes: number of completed bytes
  *
  * The block_rq_complete tracepoint event indicates that some portion
  * of operation request has been completed by the device driver.  If
@@ -139,11 +140,37 @@ DEFINE_EVENT(block_rq_with_error, block_rq_requeue,
  * do for the request. If @rq->bio is non-NULL then there is
  * additional work required to complete the request.
  */
-DEFINE_EVENT(block_rq_with_error, block_rq_complete,
+TRACE_EVENT(block_rq_complete,
 
-       TP_PROTO(struct request_queue *q, struct request *rq),
+       TP_PROTO(struct request_queue *q, struct request *rq,
+                unsigned int nr_bytes),
 
-       TP_ARGS(q, rq)
+       TP_ARGS(q, rq, nr_bytes),
+
+       TP_STRUCT__entry(
+               __field(  dev_t,        dev                     )
+               __field(  sector_t,     sector                  )
+               __field(  unsigned int, nr_sector               )
+               __field(  int,          errors                  )
+               __array(  char,         rwbs,   RWBS_LEN        )
+               __dynamic_array( char,  cmd,    blk_cmd_buf_len(rq)     )
+       ),
+
+       TP_fast_assign(
+               __entry->dev       = rq->rq_disk ? disk_devt(rq->rq_disk) : 0;
+               __entry->sector    = blk_rq_pos(rq);
+               __entry->nr_sector = nr_bytes >> 9;
+               __entry->errors    = rq->errors;
+
+               blk_fill_rwbs(__entry->rwbs, rq->cmd_flags, nr_bytes);
+               blk_dump_cmd(__get_str(cmd), rq);
+       ),
+
+       TP_printk("%d,%d %s (%s) %llu + %u [%d]",
+                 MAJOR(__entry->dev), MINOR(__entry->dev),
+                 __entry->rwbs, __get_str(cmd),
+                 (unsigned long long)__entry->sector,
+                 __entry->nr_sector, __entry->errors)
 );
 
 DECLARE_EVENT_CLASS(block_rq,

diff --git a/kernel/trace/blktrace.c b/kernel/trace/blktrace.c
index b418cb0d72424ab454e66e3cde881784ce1f0fad..4f3a3c03eadbf252545e9fc3259c34ff3f4da636 100644 (file)
--- a/kernel/trace/blktrace.c
+++ b/kernel/trace/blktrace.c
@@ -702,6 +702,7 @@ void blk_trace_shutdown(struct request_queue *q)
  * blk_add_trace_rq - Add a trace for a request oriented action
  * @q:         queue the io is for
  * @rq:                the source request
+ * @nr_bytes:  number of completed bytes
  * @what:      the action
  *
  * Description:
@@ -709,7 +710,7 @@ void blk_trace_shutdown(struct request_queue *q)
  *
  **/
 static void blk_add_trace_rq(struct request_queue *q, struct request *rq,
-                            u32 what)
+                            unsigned int nr_bytes, u32 what)
 {
        struct blk_trace *bt = q->blk_trace;
 
@@ -718,11 +719,11 @@ static void blk_add_trace_rq(struct request_queue *q, struct request *rq,
 
        if (rq->cmd_type == REQ_TYPE_BLOCK_PC) {
                what |= BLK_TC_ACT(BLK_TC_PC);
-               __blk_add_trace(bt, 0, blk_rq_bytes(rq), rq->cmd_flags,
+               __blk_add_trace(bt, 0, nr_bytes, rq->cmd_flags,
                                what, rq->errors, rq->cmd_len, rq->cmd);
        } else  {
                what |= BLK_TC_ACT(BLK_TC_FS);
-               __blk_add_trace(bt, blk_rq_pos(rq), blk_rq_bytes(rq),
+               __blk_add_trace(bt, blk_rq_pos(rq), nr_bytes,
                                rq->cmd_flags, what, rq->errors, 0, NULL);
        }
 }
@@ -730,33 +731,34 @@ static void blk_add_trace_rq(struct request_queue *q, struct request *rq,
 static void blk_add_trace_rq_abort(void *ignore,
                                   struct request_queue *q, struct request *rq)
 {
-       blk_add_trace_rq(q, rq, BLK_TA_ABORT);
+       blk_add_trace_rq(q, rq, blk_rq_bytes(rq), BLK_TA_ABORT);
 }
 
 static void blk_add_trace_rq_insert(void *ignore,
                                    struct request_queue *q, struct request *rq)
 {
-       blk_add_trace_rq(q, rq, BLK_TA_INSERT);
+       blk_add_trace_rq(q, rq, blk_rq_bytes(rq), BLK_TA_INSERT);
 }
 
 static void blk_add_trace_rq_issue(void *ignore,
                                   struct request_queue *q, struct request *rq)
 {
-       blk_add_trace_rq(q, rq, BLK_TA_ISSUE);
+       blk_add_trace_rq(q, rq, blk_rq_bytes(rq), BLK_TA_ISSUE);
 }
 
 static void blk_add_trace_rq_requeue(void *ignore,
                                     struct request_queue *q,
                                     struct request *rq)
 {
-       blk_add_trace_rq(q, rq, BLK_TA_REQUEUE);
+       blk_add_trace_rq(q, rq, blk_rq_bytes(rq), BLK_TA_REQUEUE);
 }
 
 static void blk_add_trace_rq_complete(void *ignore,
                                      struct request_queue *q,
-                                     struct request *rq)
+                                     struct request *rq,
+                                     unsigned int nr_bytes)
 {
-       blk_add_trace_rq(q, rq, BLK_TA_COMPLETE);
+       blk_add_trace_rq(q, rq, nr_bytes, BLK_TA_COMPLETE);
 }
 
 /**