Hello,
Kernel is 2.6.9-rc1-mm5. I just found this on dmesg. Not sure what the box was
doing at that time:
Badness in cfq_sort_rr_list at drivers/block/cfq-iosched.c:428
[<c01e3674>] cfq_add_crq_rb+0xe2/0x144
[<c01e4215>] cfq_enqueue+0x33/0x5f
[<c01e42ad>] cfq_insert_request+0x6c/0xe3
[<c01de2d2>] __elv_add_request+0x3f/0x79
[<c01e0940>] __make_request+0x402/0x449
[<c01e0aa2>] generic_make_request+0x11b/0x12d
[<c01e0b5f>] submit_bio+0xab/0xb3
[<c0156261>] mpage_bio_submit+0x23/0x29
[<c015658d>] do_mpage_readpage+0x242/0x29d
[<e0b97fdc>] xfs_iomap+0x3be/0x3cc [xfs]
[<c0197d4f>] radix_tree_node_alloc+0x13/0x46
[<c012736b>] add_to_page_cache+0x2f/0x64
[<c0156680>] mpage_readpages+0x98/0x10a
[<c016fd6d>] reiserfs_get_block+0x0/0x109d
[<c02b517a>] arp_bind_neighbour+0x3f/0x6a
[<c0295886>] rt_intern_hash+0x2d8/0x2e8
[<c0170e20>] reiserfs_readpages+0x16/0x1a
[<c016fd6d>] reiserfs_get_block+0x0/0x109d
[<c012cae5>] read_pages+0x27/0xec
[<c012a89d>] buffered_rmqueue+0x13b/0x166
[<c012a9c7>] __alloc_pages+0xff/0x2de
[<c02878af>] kfree_skbmem+0x17/0x1c
[<c012cdd9>] do_page_cache_readahead+0xe8/0x109
[<c012cf36>] page_cache_readahead+0x13c/0x1a7
[<c01278ad>] do_generic_mapping_read+0xcd/0x33a
[<c0127d47>] __generic_file_aio_read+0x165/0x17f
[<c0127b1a>] file_read_actor+0x0/0xc8
[<c0127e57>] generic_file_read+0xaa/0xc3
[<c01223cd>] autoremove_wake_function+0x0/0x3a
[<c013d705>] vfs_read+0xae/0xd8
[<c0144fdd>] kernel_read+0x38/0x41
[<c0145760>] prepare_binprm+0xbd/0xc8
[<c0145b3c>] do_execve+0x146/0x247
[<c0146f61>] getname+0x5d/0x94
[<c01038fb>] sys_execve+0x2b/0x59
[<c0104975>] sysenter_past_esp+0x52/0x71
Do you need more info?
Thanks,
Norberto
On Wed, Sep 15 2004, Norberto Bensa wrote:
> Hello,
>
> Kernel is 2.6.9-rc1-mm5. I just found this on dmesg. Not sure what the box was
> doing at that time:
>
> Badness in cfq_sort_rr_list at drivers/block/cfq-iosched.c:428
> [<c01e3674>] cfq_add_crq_rb+0xe2/0x144
> [<c01e4215>] cfq_enqueue+0x33/0x5f
> [<c01e42ad>] cfq_insert_request+0x6c/0xe3
> [<c01de2d2>] __elv_add_request+0x3f/0x79
> [<c01e0940>] __make_request+0x402/0x449
It's harmless. I've sent this incremental patch to Andrew that fixes
this error and some others.
This update:
- Removes some debugging code and the dprintk() stuff
- Detects when tagging is used or not, defines a threshold of
CFQ_MAX_TAG (default: 4) for when we change from non-tagged to tagged
operations. This affects accounting.
- Fix a bug where the rr_list was sorted badly. Also make sure we always
keep it sorted, and add some logic to detect when to resort. This
could trigger a harmless WARN_ON at line 428.
- Don't set ->service_start when queue is removed from rr_list, this
could starve a queue if it was quickly readded to the rr_list again.
In that case, we never would hit the 1 second interval for aging the
service_used down.
- Cache jiffies in some function instead of re-reading it 2-3 times.
You can fold this in with the cfq-v2 patch if you want.
Signed-off-by: Jens Axboe <[email protected]>
--- drivers/block/cfq-iosched.c~ 2004-09-13 20:06:30.425042983 +0200
+++ drivers/block/cfq-iosched.c 2004-09-13 20:14:33.934118844 +0200
@@ -22,14 +22,6 @@
#include <linux/rbtree.h>
#include <linux/mempool.h>
-#undef CFQ_DEBUG
-
-#ifdef CFQ_DEBUG
-#define dprintk(fmt, args...) printk(KERN_ERR "cfq: " fmt, ##args)
-#else
-#define dprintk(fmt, args...)
-#endif
-
static unsigned long max_elapsed_crq;
static unsigned long max_elapsed_dispatch;
@@ -84,6 +76,11 @@
#define rq_rb_key(rq) (rq)->sector
/*
+ * threshold for switching off non-tag accounting
+ */
+#define CFQ_MAX_TAG (4)
+
+/*
* sort key types and names
*/
enum {
@@ -125,18 +122,21 @@
sector_t last_sector;
+ int rq_in_driver;
+
/*
* tunables, see top of file
*/
unsigned int cfq_quantum;
unsigned int cfq_queued;
- unsigned int cfq_tagged;
unsigned int cfq_fifo_expire_r;
unsigned int cfq_fifo_expire_w;
unsigned int cfq_fifo_batch_expire;
unsigned int cfq_back_penalty;
unsigned int cfq_back_max;
unsigned int find_best_crq;
+
+ unsigned int cfq_tagged;
};
struct cfq_queue {
@@ -170,14 +170,12 @@
unsigned long service_start;
unsigned long service_used;
+ unsigned int max_rate;
+
/* number of requests that have been handed to the driver */
int in_flight;
/* number of currently allocated requests */
int alloc_limit[2];
-
-#ifdef CFQ_DEBUG
- char name[16];
-#endif
};
struct cfq_rq {
@@ -307,7 +305,7 @@
if (blk_barrier_rq(rq))
break;
-
+
if (distance < abs(s1 - rq->sector + rq->nr_sectors)) {
distance = abs(s1 - rq->sector +rq->nr_sectors);
last = rq->sector + rq->nr_sectors;
@@ -404,11 +402,42 @@
cfqq->next_crq = cfq_find_next_crq(cfqq->cfqd, cfqq, crq);
}
-static inline void
-cfq_sort_rr_list(struct cfq_queue *cfqq)
+static int cfq_check_sort_rr_list(struct cfq_queue *cfqq)
+{
+ struct list_head *head = &cfqq->cfqd->rr_list;
+ struct list_head *next, *prev;
+
+ /*
+ * list might still be ordered
+ */
+ next = cfqq->cfq_list.next;
+ if (next != head) {
+ struct cfq_queue *cnext = list_entry_cfqq(next);
+
+ if (cfqq->service_used > cnext->service_used)
+ return 1;
+ }
+
+ prev = cfqq->cfq_list.prev;
+ if (prev != head) {
+ struct cfq_queue *cprev = list_entry_cfqq(prev);
+
+ if (cfqq->service_used < cprev->service_used)
+ return 1;
+ }
+
+ return 0;
+}
+
+static void cfq_sort_rr_list(struct cfq_queue *cfqq, int new_queue)
{
struct list_head *entry = &cfqq->cfqd->rr_list;
+ if (!cfqq->on_rr)
+ return;
+ if (!new_queue && !cfq_check_sort_rr_list(cfqq))
+ return;
+
list_del(&cfqq->cfq_list);
/*
@@ -446,21 +475,16 @@
static inline void
cfq_add_cfqq_rr(struct cfq_data *cfqd, struct cfq_queue *cfqq)
{
- BUG_ON(cfqq->on_rr);
-
/*
* it's currently on the empty list
*/
- cfq_sort_rr_list(cfqq);
cfqq->on_rr = 1;
cfqd->busy_queues++;
- /*
- * if the queue is on the empty_list, service_start was the time
- * where it was deleted from the rr_list.
- */
if (time_after(jiffies, cfqq->service_start + cfq_service))
cfqq->service_used >>= 3;
+
+ cfq_sort_rr_list(cfqq, 1);
}
static inline void
@@ -468,7 +492,6 @@
{
list_move(&cfqq->cfq_list, &cfqd->empty_list);
cfqq->on_rr = 0;
- cfqq->service_start = jiffies;
BUG_ON(!cfqd->busy_queues);
cfqd->busy_queues--;
@@ -492,10 +515,8 @@
rb_erase(&crq->rb_node, &cfqq->sort_list);
RB_CLEAR_COLOR(&crq->rb_node);
- if (RB_EMPTY(&cfqq->sort_list) && cfqq->on_rr) {
- dprintk("moving 0x%p empty_list\n", cfqq);
+ if (RB_EMPTY(&cfqq->sort_list) && cfqq->on_rr)
cfq_del_cfqq_rr(cfqd, cfqq);
- }
}
}
@@ -541,11 +562,8 @@
rb_insert_color(&crq->rb_node, &cfqq->sort_list);
- if (!cfqq->on_rr) {
+ if (!cfqq->on_rr)
cfq_add_cfqq_rr(cfqd, cfqq);
- dprintk("moving to rr list %d\n", cfqd->busy_queues);
- } else
- dprintk("already on rr list %d\n", cfqd->busy_queues);
/*
* check if this request is a better next-serve candidate
@@ -590,11 +608,30 @@
return NULL;
}
-static void cfq_remove_request(request_queue_t *q, struct request *rq)
+/*
+ * make sure the service time gets corrected on reissue of this request
+ */
+static void cfq_requeue_request(request_queue_t *q, struct request *rq)
{
struct cfq_rq *crq = RQ_DATA(rq);
- dprintk("removing 0x%p\n", rq);
+ if (crq) {
+ struct cfq_queue *cfqq = crq->cfq_queue;
+
+ if (cfqq->cfqd->cfq_tagged) {
+ cfqq->service_used--;
+ cfq_sort_rr_list(cfqq, 0);
+ }
+
+ crq->accounted = 0;
+ cfqq->cfqd->rq_in_driver--;
+ }
+ list_add(&rq->queuelist, &q->queue_head);
+}
+
+static void cfq_remove_request(request_queue_t *q, struct request *rq)
+{
+ struct cfq_rq *crq = RQ_DATA(rq);
if (crq) {
cfq_remove_merge_hints(q, crq);
@@ -730,20 +767,21 @@
struct cfq_data *cfqd = cfqq->cfqd;
const int reads = !list_empty(&cfqq->fifo[0]);
const int writes = !list_empty(&cfqq->fifo[1]);
+ unsigned long now = jiffies;
struct cfq_rq *crq;
- if (jiffies - cfqq->last_fifo_expire < cfqd->cfq_fifo_batch_expire)
+ if (time_before(now, cfqq->last_fifo_expire + cfqd->cfq_fifo_batch_expire))
return NULL;
crq = RQ_DATA(list_entry(cfqq->fifo[0].next, struct request, queuelist));
- if (reads && time_after(jiffies, crq->queue_start + cfqd->cfq_fifo_expire_r)) {
- cfqq->last_fifo_expire = jiffies;
+ if (reads && time_after(now, crq->queue_start + cfqd->cfq_fifo_expire_r)) {
+ cfqq->last_fifo_expire = now;
return crq;
}
crq = RQ_DATA(list_entry(cfqq->fifo[1].next, struct request, queuelist));
- if (writes && time_after(jiffies, crq->queue_start + cfqd->cfq_fifo_expire_w)) {
- cfqq->last_fifo_expire = jiffies;
+ if (writes && time_after(now, crq->queue_start + cfqd->cfq_fifo_expire_w)) {
+ cfqq->last_fifo_expire = now;
return crq;
}
@@ -822,7 +860,8 @@
static inline void cfq_account_dispatch(struct cfq_rq *crq)
{
struct cfq_queue *cfqq = crq->cfq_queue;
- unsigned long elapsed = jiffies - crq->queue_start;
+ struct cfq_data *cfqd = cfqq->cfqd;
+ unsigned long now, elapsed;
/*
* accounted bit is necessary since some drivers will call
@@ -831,52 +870,62 @@
if (crq->accounted)
return;
+ now = jiffies;
+ if (cfqq->service_start == ~0UL)
+ cfqq->service_start = now;
+
/*
* on drives with tagged command queueing, command turn-around time
* doesn't necessarily reflect the time spent processing this very
* command inside the drive. so do the accounting differently there,
* by just sorting on the number of requests
*/
- if (cfqq->cfqd->cfq_tagged) {
- if (time_after(jiffies, cfqq->service_start + cfq_service)) {
- cfqq->service_start = jiffies;
+ if (cfqd->cfq_tagged) {
+ if (time_after(now, cfqq->service_start + cfq_service)) {
+ cfqq->service_start = now;
cfqq->service_used /= 10;
}
cfqq->service_used++;
+ cfq_sort_rr_list(cfqq, 0);
}
+ elapsed = now - crq->queue_start;
if (elapsed > max_elapsed_dispatch)
max_elapsed_dispatch = elapsed;
crq->accounted = 1;
- crq->service_start = jiffies;
+ crq->service_start = now;
+
+ if (++cfqd->rq_in_driver >= CFQ_MAX_TAG && !cfqd->cfq_tagged) {
+ cfqq->cfqd->cfq_tagged = 1;
+ printk("cfq: depth %d reached, tagging now on\n", CFQ_MAX_TAG);
+ }
}
static inline void
cfq_account_completion(struct cfq_queue *cfqq, struct cfq_rq *crq)
{
- unsigned long start_val = cfqq->service_used;
+ struct cfq_data *cfqd = cfqq->cfqd;
+
+ WARN_ON(!cfqd->rq_in_driver);
+ cfqd->rq_in_driver--;
- if (!cfqq->cfqd->cfq_tagged) {
- unsigned long duration = jiffies - crq->service_start;
+ if (!cfqd->cfq_tagged) {
+ unsigned long now = jiffies;
+ unsigned long duration = now - crq->service_start;
- if (time_after(jiffies, cfqq->service_start + cfq_service)) {
- cfqq->service_start = jiffies;
+ if (time_after(now, cfqq->service_start + cfq_service)) {
+ cfqq->service_start = now;
cfqq->service_used >>= 3;
}
cfqq->service_used += duration;
+ cfq_sort_rr_list(cfqq, 0);
if (duration > max_elapsed_crq)
max_elapsed_crq = duration;
}
-
- /*
- * make sure list stays properly sorted, but only do so if necessary
- */
- if (cfqq->on_rr && cfqq->service_used != start_val)
- cfq_sort_rr_list(cfqq);
}
static struct request *cfq_next_request(request_queue_t *q)
@@ -913,13 +962,9 @@
{
BUG_ON(!atomic_read(&cfqq->ref));
- dprintk("cfq_put_queue 0x%p, ref\n", atomic_read(&cfqq->ref));
-
if (!atomic_dec_and_test(&cfqq->ref))
return;
- dprintk("killing queue 0x%p/%s\n", cfqq, cfqq->name);
-
BUG_ON(rb_first(&cfqq->sort_list));
BUG_ON(cfqq->on_rr);
@@ -1163,11 +1208,8 @@
hlist_add_head(&cfqq->cfq_hash, &cfqd->cfq_hash[hashval]);
atomic_set(&cfqq->ref, 0);
cfqq->cfqd = cfqd;
-#ifdef CFQ_DEBUG
- strncpy(cfqq->name, current->comm, sizeof(cfqq->name)-1);
-#endif
- dprintk("cfqq set up for 0x%p/%s\n", cfqq, cfqq->name);
cfqq->key_type = cfqd->key_type;
+ cfqq->service_start = ~0UL;
}
if (new_cfqq)
@@ -1212,17 +1254,14 @@
switch (where) {
case ELEVATOR_INSERT_BACK:
- dprintk("adding back 0x%p\n", rq);
while (cfq_dispatch_requests(q, cfqd->cfq_quantum))
;
list_add_tail(&rq->queuelist, &q->queue_head);
break;
case ELEVATOR_INSERT_FRONT:
- dprintk("adding front 0x%p\n", rq);
list_add(&rq->queuelist, &q->queue_head);
break;
case ELEVATOR_INSERT_SORT:
- dprintk("adding sort 0x%p\n", rq);
BUG_ON(!blk_fs_request(rq));
cfq_enqueue(cfqd, crq);
break;
@@ -1511,7 +1599,6 @@
cfqd->cfq_back_max = cfq_back_max;
cfqd->cfq_back_penalty = cfq_back_penalty;
- dprintk("cfq on queue 0x%p\n", q);
return 0;
out_spare:
mempool_destroy(cfqd->crq_pool);
@@ -1632,7 +1719,7 @@
}
len += sprintf(page+len, " busy queues total: %d\n", i);
queues = i;
-
+
len += sprintf(page+len, "Empty queue list:\n");
i = 0;
list_for_each(entry, &cfqd->empty_list) {
@@ -1654,7 +1741,6 @@
}
SHOW_FUNCTION(cfq_quantum_show, cfqd->cfq_quantum);
SHOW_FUNCTION(cfq_queued_show, cfqd->cfq_queued);
-SHOW_FUNCTION(cfq_tagged_show, cfqd->cfq_tagged);
SHOW_FUNCTION(cfq_fifo_expire_r_show, cfqd->cfq_fifo_expire_r);
SHOW_FUNCTION(cfq_fifo_expire_w_show, cfqd->cfq_fifo_expire_w);
SHOW_FUNCTION(cfq_fifo_batch_expire_show, cfqd->cfq_fifo_batch_expire);
@@ -1675,7 +1761,6 @@
}
STORE_FUNCTION(cfq_quantum_store, &cfqd->cfq_quantum, 1, UINT_MAX);
STORE_FUNCTION(cfq_queued_store, &cfqd->cfq_queued, 1, UINT_MAX);
-STORE_FUNCTION(cfq_tagged_store, &cfqd->cfq_tagged, 0, 1);
STORE_FUNCTION(cfq_fifo_expire_r_store, &cfqd->cfq_fifo_expire_r, 1, UINT_MAX);
STORE_FUNCTION(cfq_fifo_expire_w_store, &cfqd->cfq_fifo_expire_w, 1, UINT_MAX);
STORE_FUNCTION(cfq_fifo_batch_expire_store, &cfqd->cfq_fifo_batch_expire, 0, UINT_MAX);
@@ -1694,11 +1779,6 @@
.show = cfq_queued_show,
.store = cfq_queued_store,
};
-static struct cfq_fs_entry cfq_tagged_entry = {
- .attr = {.name = "tagged", .mode = S_IRUGO | S_IWUSR },
- .show = cfq_tagged_show,
- .store = cfq_tagged_store,
-};
static struct cfq_fs_entry cfq_fifo_expire_r_entry = {
.attr = {.name = "fifo_expire_sync", .mode = S_IRUGO | S_IWUSR },
.show = cfq_fifo_expire_r_show,
@@ -1746,7 +1826,6 @@
static struct attribute *default_attrs[] = {
&cfq_quantum_entry.attr,
&cfq_queued_entry.attr,
- &cfq_tagged_entry.attr,
&cfq_fifo_expire_r_entry.attr,
&cfq_fifo_expire_w_entry.attr,
&cfq_fifo_batch_expire_entry.attr,
@@ -1805,6 +1884,7 @@
.elevator_next_req_fn = cfq_next_request,
.elevator_add_req_fn = cfq_insert_request,
.elevator_remove_req_fn = cfq_remove_request,
+ .elevator_requeue_req_fn = cfq_requeue_request,
.elevator_queue_empty_fn = cfq_queue_empty,
.elevator_completed_req_fn = cfq_completed_request,
.elevator_former_req_fn = cfq_former_request,
--
Jens Axboe