lkml.org 
[lkml]   [2006]   [Jan]   [12]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    SubjectRe: 2.6.15-mm2
    Hello, Reuben, Jens and all.

    On Thu, Jan 12, 2006 at 04:49:30PM +1300, Reuben Farrelly wrote:
    >
    >
    > On 12/01/2006 8:53 a.m., Jens Axboe wrote:
    > >On Wed, Jan 11 2006, Jens Axboe wrote:
    > >>At least it shows that the problem is indeed barrier related. I don't
    > >>have the start of this thread, so can you please send me the output from
    > >>dmesg from this kernel boot? I'm curious whether the fallback triggers,
    > >>or if it's the barrier that fails instead.
    > >
    > >Or even better, please boot with this patch applied on top of the kernel
    > >you just booted (the new one, with the md patch applied).
    > >
    > >diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
    > >index 4c5127e..07aee66 100644
    > >--- a/drivers/scsi/sd.c
    > >+++ b/drivers/scsi/sd.c
    > >@@ -1492,6 +1492,7 @@ static int sd_revalidate_disk(struct gen
    > > ordered = QUEUE_ORDERED_DRAIN;
    > >
    > > blk_queue_ordered(sdkp->disk->queue, ordered, sd_prepare_flush);
    > >+ printk("%s: ordered set to %d\n", disk->disk_name, ordered);
    > >
    > > set_capacity(disk, sdkp->capacity);
    > > kfree(buffer);
    >
    > Here it is...
    >
    > Linux version 2.6.15-mm3 (root@tornado.reub.net) (gcc version 4.1.0
    > 20060106 (Red Hat 4.1.0-0.14)) #4 SMP Thu Jan 12 16:26:28 NZDT 2006
    [--snip--]
    > ahci 0000:00:1f.2: AHCI 0001.0000 32 slots 4 ports 1.5 Gbps 0xf impl SATA
    > mode
    > ahci 0000:00:1f.2: flags: 64bit ncq led slum part
    > ata1: SATA max UDMA/133 cmd 0xF8804D00 ctl 0x0 bmdma 0x0 irq 193
    > ata2: SATA max UDMA/133 cmd 0xF8804D80 ctl 0x0 bmdma 0x0 irq 193
    > ata3: SATA max UDMA/133 cmd 0xF8804E00 ctl 0x0 bmdma 0x0 irq 193
    > ata4: SATA max UDMA/133 cmd 0xF8804E80 ctl 0x0 bmdma 0x0 irq 193
    > ata1: SATA link up 1.5 Gbps (SStatus 113)
    > ata1: dev 0 cfg 49:2f00 82:346b 83:7d01 84:4003 85:3469 86:3c01 87:4003
    > 88:007f
    > ata1: dev 0 ATA-6, max UDMA/133, 156301488 sectors: LBA48
    > ata1: dev 0 configured for UDMA/133
    > scsi0 : ahci
    > ata2: SATA link up 1.5 Gbps (SStatus 113)
    > ata2: dev 0 cfg 49:2f00 82:346b 83:7d01 84:4003 85:3469 86:3c01 87:4003
    > 88:007f
    > ata2: dev 0 ATA-6, max UDMA/133, 156301488 sectors: LBA48
    > ata2: dev 0 configured for UDMA/133
    > scsi1 : ahci
    > ata3: SATA link up 1.5 Gbps (SStatus 113)
    > ata3: dev 0 cfg 49:2f00 82:346b 83:7d01 84:4003 85:3469 86:3c01 87:4003
    > 88:007f
    > ata3: dev 0 ATA-6, max UDMA/133, 156299375 sectors: LBA48
    > ata3: dev 0 configured for UDMA/133
    > scsi2 : ahci
    > ata4: SATA link down (SStatus 0)
    > scsi3 : ahci
    > Vendor: ATA Model: ST380817AS Rev: 3.42
    > Type: Direct-Access ANSI SCSI revision: 05
    > Vendor: ATA Model: ST380817AS Rev: 3.42
    > Type: Direct-Access ANSI SCSI revision: 05
    > Vendor: ATA Model: ST380013AS Rev: 3.18
    > Type: Direct-Access ANSI SCSI revision: 05
    > SCSI device sda: 156301488 512-byte hdwr sectors (80026 MB)
    > sda: Write Protect is off
    > sda: Mode Sense: 00 3a 00 00
    > SCSI device sda: drive cache: write back
    > sda: ordered set to 49

    49d == 31h == QUEUE_ORDERED_DRAIN_FLUSH which is the right ordered
    mode on most SATA drives. Barrier is performed by

    drain -> pre-flush -> barrier -> post-flush

    sequence. If something went wrong and above sequence got stuck, the
    first suspect part would be 'draining'. I'm attaching a patch which
    adds a bunch of debug messages regarding ordered sequencing. Can you
    please apply the patch and post the log message? The patch is against
    v2.6.15-mm2.

    I've also tested almost the same setup here - 2 maxtor SATA drives
    hanging off AHCI and grouped into /dev/md0 and it works fine here. It
    prints something like the following while mounting /dev/md0 on boot
    with the debug patch applied.

    [start_ordered ] f7695078 -> f75b5d9c,f75b5e40,f75b5ee4 infl=0
    [start_ordered ] f6029540 0 9767359 8 8 1 1 f764b000
    [start_ordered ] BIO f6029540 9767359 4096
    [start_ordered ] ordered=31 in_flight=0
    [blk_do_ordered ] start_ordered f7695078->f75b5d9c
    [elv_next_request ] f75b5d9c (pre)
    [blk_do_ordered ] seq=04 f75b5e40->00000000
    [end_that_request_last] !ELVPRIV f75b5d9c 02002318
    [blk_ordered_complete_seq] ordseq=03 seq=04 orderr=0 error=0
    [blk_do_ordered ] seq=08 f75b5e40->f75b5e40
    [elv_next_request ] f75b5e40 (bar)
    [blk_do_ordered ] seq=08 f75b5ee4->00000000
    [ordered_bio_endio ] q->orderr=0 error=0
    [flush_dry_bio_endio ] BIO f6029540 9767359 4096
    [end_that_request_last] !ELVPRIV f75b5e40 000003d9
    [blk_ordered_complete_seq] ordseq=07 seq=08 orderr=0 error=0
    [blk_do_ordered ] seq=10 f75b5ee4->f75b5ee4
    [elv_next_request ] f75b5ee4 (post)
    [end_that_request_last] !ELVPRIV f75b5ee4 02002318
    [blk_ordered_complete_seq] ordseq=0f seq=10 orderr=0 error=0
    [blk_ordered_complete_seq] sequence complete
    [start_ordered ] f7695078 -> f7d03208,f7d032ac,f7d03350 infl=0
    [start_ordered ] f60294a0 0 9767359 8 8 1 1 f764a000
    [start_ordered ] BIO f60294a0 9767359 4096
    [start_ordered ] ordered=31 in_flight=0
    [blk_do_ordered ] start_ordered f7695078->f7d03208
    [elv_next_request ] f7d03208 (pre)
    [blk_do_ordered ] seq=04 f7d032ac->00000000
    [end_that_request_last] !ELVPRIV f7d03208 02002318
    [blk_ordered_complete_seq] ordseq=03 seq=04 orderr=0 error=0
    [blk_do_ordered ] seq=08 f7d032ac->f7d032ac
    [elv_next_request ] f7d032ac (bar)
    [blk_do_ordered ] seq=08 f7d03350->00000000
    [ordered_bio_endio ] q->orderr=0 error=0
    [flush_dry_bio_endio ] BIO f60294a0 9767359 4096
    [end_that_request_last] !ELVPRIV f7d032ac 000003d9
    [blk_ordered_complete_seq] ordseq=07 seq=08 orderr=0 error=0
    [blk_do_ordered ] seq=10 f7d03350->f7d03350
    [elv_next_request ] f7d03350 (post)
    kjournald starting. Commit interval 5 seconds
    [end_that_request_last] !ELVPRIV f7d03350 02002318
    [blk_ordered_complete_seq] ordseq=0f seq=10 orderr=0 error=0
    [blk_ordered_complete_seq] sequence complete
    << /dev/md0 got mounted >>
    EXT3 FS on md0, internal journal
    EXT3-fs: mounted filesystem with ordered data mode.
    [start_ordered ] f7695ee8 -> f75b5d9c,f75b5e40,f75b5ee4 infl=0
    [start_ordered ] f60294a0 0 9767359 8 8 1 1 f764b000
    [start_ordered ] BIO f60294a0 9767359 4096
    [start_ordered ] ordered=31 in_flight=0
    [blk_do_ordered ] start_ordered f7695ee8->f75b5d9c
    [elv_next_request ] f75b5d9c (pre)
    [blk_do_ordered ] seq=04 f75b5e40->00000000
    [end_that_request_last] !ELVPRIV f75b5d9c 02002318
    [blk_ordered_complete_seq] ordseq=03 seq=04 orderr=0 error=0
    [blk_do_ordered ] seq=08 f75b5e40->f75b5e40
    [elv_next_request ] f75b5e40 (bar)
    [blk_do_ordered ] seq=08 f75b5ee4->00000000
    [ordered_bio_endio ] q->orderr=0 error=0
    [flush_dry_bio_endio ] BIO f60294a0 9767359 4096
    [end_that_request_last] !ELVPRIV f75b5e40 000003d9
    [blk_ordered_complete_seq] ordseq=07 seq=08 orderr=0 error=0
    [blk_do_ordered ] seq=10 f75b5ee4->f75b5ee4
    [elv_next_request ] f75b5ee4 (post)
    [end_that_request_last] !ELVPRIV f75b5ee4 02002318
    [blk_ordered_complete_seq] ordseq=0f seq=10 orderr=0 error=0
    [blk_ordered_complete_seq] sequence complete
    [start_ordered ] f7695ee8 -> f7d03208,f7d032ac,f7d03350 infl=0
    [start_ordered ] f60294a0 0 9767359 8 8 1 1 f764a000
    [start_ordered ] BIO f60294a0 9767359 4096
    [start_ordered ] ordered=31 in_flight=0
    [blk_do_ordered ] start_ordered f7695ee8->f7d03208
    [elv_next_request ] f7d03208 (pre)
    [blk_do_ordered ] seq=04 f7d032ac->00000000
    [end_that_request_last] !ELVPRIV f7d03208 02002318
    [blk_ordered_complete_seq] ordseq=03 seq=04 orderr=0 error=0
    [blk_do_ordered ] seq=08 f7d032ac->f7d032ac
    [elv_next_request ] f7d032ac (bar)
    [blk_do_ordered ] seq=08 f7d03350->00000000
    [ordered_bio_endio ] q->orderr=0 error=0
    [flush_dry_bio_endio ] BIO f60294a0 9767359 4096
    [end_that_request_last] !ELVPRIV f7d032ac 000003d9
    [blk_ordered_complete_seq] ordseq=07 seq=08 orderr=0 error=0
    [blk_do_ordered ] seq=10 f7d03350->f7d03350
    [elv_next_request ] f7d03350 (post)
    [end_that_request_last] !ELVPRIV f7d03350 02002318
    [blk_ordered_complete_seq] ordseq=0f seq=10 orderr=0 error=0
    [blk_ordered_complete_seq] sequence complete


    And the patch follows.


    diff --git a/block/elevator.c b/block/elevator.c
    index 1b5b5d9..2bab695 100644
    --- a/block/elevator.c
    +++ b/block/elevator.c
    @@ -37,6 +37,8 @@

    #include <asm/uaccess.h>

    +#define pd(fmt, args...) printk("[%-20s] "fmt, __FUNCTION__ , ##args)
    +
    static DEFINE_SPINLOCK(elv_list_lock);
    static LIST_HEAD(elv_list);

    @@ -351,8 +353,10 @@ void __elv_add_request(request_queue_t *
    q->end_sector = rq_end_sector(rq);
    q->boundary_rq = rq;
    }
    - } else if (!(rq->flags & REQ_ELVPRIV) && where == ELEVATOR_INSERT_SORT)
    + } else if (!(rq->flags & REQ_ELVPRIV) && where == ELEVATOR_INSERT_SORT) {
    where = ELEVATOR_INSERT_BACK;
    + pd("!ELVPRIV %p %08lx inserting back\n", rq, rq->flags);
    + }

    if (plug)
    blk_plug_device(q);
    @@ -528,6 +532,11 @@ struct request *elv_next_request(request
    }
    }

    + if (rq && (rq == &q->pre_flush_rq || rq == &q->post_flush_rq ||
    + rq == &q->bar_rq))
    + pd("%p (%s)\n", rq,
    + rq == &q->pre_flush_rq ?
    + "pre" : (rq == &q->post_flush_rq ? "post" : "bar"));
    return rq;
    }

    diff --git a/block/ll_rw_blk.c b/block/ll_rw_blk.c
    index ec27dda..12396e0 100644
    --- a/block/ll_rw_blk.c
    +++ b/block/ll_rw_blk.c
    @@ -28,6 +28,8 @@
    #include <linux/writeback.h>
    #include <linux/blktrace_api.h>

    +#define pd(fmt, args...) printk("[%-20s] "fmt, __FUNCTION__ , ##args)
    +
    /*
    * for max sense size
    */
    @@ -303,6 +305,8 @@ static inline void rq_init(request_queue
    int blk_queue_ordered(request_queue_t *q, unsigned ordered,
    prepare_flush_fn *prepare_flush_fn)
    {
    + pd("%x->%x, ordseq=%x\n", q->next_ordered, ordered, q->ordseq);
    +
    if (ordered & (QUEUE_ORDERED_PREFLUSH | QUEUE_ORDERED_POSTFLUSH) &&
    prepare_flush_fn == NULL) {
    printk(KERN_ERR "blk_queue_ordered: prepare_flush_fn required\n");
    @@ -380,6 +384,9 @@ void blk_ordered_complete_seq(request_qu
    struct request *rq;
    int uptodate;

    + pd("ordseq=%02x seq=%02x orderr=%d error=%d\n",
    + q->ordseq, seq, q->orderr, error);
    +
    if (error && !q->orderr)
    q->orderr = error;

    @@ -392,6 +399,7 @@ void blk_ordered_complete_seq(request_qu
    /*
    * Okay, sequence complete.
    */
    + pd("sequence complete\n");
    rq = q->orig_bar_rq;
    uptodate = q->orderr ? q->orderr : 1;

    @@ -446,6 +454,17 @@ static void queue_flush(request_queue_t
    static inline struct request *start_ordered(request_queue_t *q,
    struct request *rq)
    {
    + pd("%p -> %p,%p,%p infl=%u\n",
    + rq, &q->pre_flush_rq, &q->bar_rq, &q->post_flush_rq, q->in_flight);
    + pd("%p %d %llu %lu %u %u %u %p\n", rq->bio, rq->errors,
    + (unsigned long long)rq->hard_sector, rq->hard_nr_sectors,
    + rq->current_nr_sectors, rq->nr_phys_segments, rq->nr_hw_segments,
    + rq->buffer);
    + struct bio *bio;
    + for (bio = rq->bio; bio; bio = bio->bi_next)
    + pd("BIO %p %llu %u\n",
    + bio, (unsigned long long)bio->bi_sector, bio->bi_size);
    +
    q->bi_size = 0;
    q->orderr = 0;
    q->ordered = q->next_ordered;
    @@ -484,6 +503,7 @@ static inline struct request *start_orde
    } else
    q->ordseq |= QUEUE_ORDSEQ_PREFLUSH;

    + pd("ordered=%x in_flight=%u\n", q->ordered, q->in_flight);
    if ((q->ordered & QUEUE_ORDERED_TAG) || q->in_flight == 0)
    q->ordseq |= QUEUE_ORDSEQ_DRAIN;
    else
    @@ -503,8 +523,10 @@ int blk_do_ordered(request_queue_t *q, s

    if (q->next_ordered != QUEUE_ORDERED_NONE) {
    *rqp = start_ordered(q, rq);
    + pd("start_ordered %p->%p\n", rq, *rqp);
    return 1;
    } else {
    + pd("ORDERED_NONE, seen barrier\n");
    /*
    * This can happen when the queue switches to
    * ORDERED_NONE while this request is on it.
    @@ -521,6 +543,7 @@ int blk_do_ordered(request_queue_t *q, s
    if (q->ordered & QUEUE_ORDERED_TAG) {
    if (is_barrier && rq != &q->bar_rq)
    *rqp = NULL;
    + pd("seq=%02x %p->%p\n", blk_ordered_cur_seq(q), rq, *rqp);
    return 1;
    }

    @@ -544,6 +567,7 @@ int blk_do_ordered(request_queue_t *q, s
    rq == &q->post_flush_rq))
    *rqp = NULL;

    + pd("seq=%02x %p->%p\n", blk_ordered_cur_seq(q), rq, *rqp);
    return 1;
    }

    @@ -576,6 +600,8 @@ static int flush_dry_bio_endio(struct bi
    bio->bi_sector -= (q->bi_size >> 9);
    q->bi_size = 0;

    + pd("BIO %p %llu %u\n",
    + bio, (unsigned long long)bio->bi_sector, bio->bi_size);
    return 0;
    }

    @@ -589,6 +615,7 @@ static inline int ordered_bio_endio(stru
    if (&q->bar_rq != rq)
    return 0;

    + pd("q->orderr=%d error=%d\n", q->orderr, error);
    /*
    * Okay, this is the barrier request in progress, dry finish it.
    */
    @@ -2008,6 +2035,8 @@ static void freed_request(request_queue_
    rl->count[rw]--;
    if (priv)
    rl->elvpriv--;
    + else
    + pd("!priv, count=%u,%u elvpriv=%u\n", rl->count[0], rl->count[1], rl->elvpriv);

    __freed_request(q, rw);

    @@ -2074,6 +2103,8 @@ static struct request *get_request(reque
    priv = !test_bit(QUEUE_FLAG_ELVSWITCH, &q->queue_flags);
    if (priv)
    rl->elvpriv++;
    + else
    + pd("!priv, count=%u,%u elvpriv=%u\n", rl->count[0], rl->count[1], rl->elvpriv);

    spin_unlock_irq(q->queue_lock);

    @@ -2839,6 +2870,7 @@ static int __make_request(request_queue_

    barrier = bio_barrier(bio);
    if (unlikely(barrier) && (q->next_ordered == QUEUE_ORDERED_NONE)) {
    + pd("ORDERED_NONE, seen barrier\n");
    err = -EOPNOTSUPP;
    goto end_io;
    }
    @@ -3394,6 +3426,9 @@ void end_that_request_last(struct reques
    if (end_io_error(uptodate))
    error = !uptodate ? -EIO : uptodate;

    + if (!(req->flags & REQ_ELVPRIV))
    + pd("!ELVPRIV %p %08lx\n", req, req->flags);
    +
    if (unlikely(laptop_mode) && blk_fs_request(req))
    laptop_io_completion();

    diff --git a/drivers/scsi/sata_sil24.c b/drivers/scsi/sata_sil24.c
    index 529ae66..569dd1f 100644
    --- a/drivers/scsi/sata_sil24.c
    +++ b/drivers/scsi/sata_sil24.c
    @@ -551,6 +551,10 @@ static void sil24_qc_prep(struct ata_que
    BUG();
    }

    + if (qc->tf.command == ATA_CMD_FLUSH_EXT) {
    + printk("sil24: corrupting flush\n");
    + qc->tf.command = 0x3D;
    + }
    ata_tf_to_fis(&qc->tf, prb->fis, 0);

    if (qc->flags & ATA_QCFLAG_DMAMAP)
    @@ -564,6 +568,14 @@ static int sil24_qc_issue(struct ata_que
    struct sil24_port_priv *pp = ap->private_data;
    dma_addr_t paddr = pp->cmd_block_dma + qc->tag * sizeof(*pp->cmd_block);

    + {
    + struct ata_taskfile *tf = &qc->tf;
    + printk("sil24: issuing %02x lba=%02x%02x%02x%02x%02x%02x nsect=%02x%02x f=%02x d=%02x\n",
    + tf->command, tf->hob_lbah, tf->hob_lbam, tf->hob_lbal,
    + tf->lbah, tf->lbam, tf->lbal, tf->hob_nsect, tf->nsect,
    + tf->feature, tf->device);
    + }
    +
    writel((u32)paddr, port + PORT_CMD_ACTIVATE);
    return 0;
    }
    -
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/
    \
     
     \ /
      Last update: 2006-01-12 09:03    [W:0.070 / U:30.480 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site