archive/bio-debug

   1 ext4: debugging patches for the bio code
   2
   3 ---
   4  block/blk-core.c      |   17 ++++++++++
   5  fs/buffer.c           |   36 ++++++++++++++++++++++
   6  fs/ext4/inode.c       |   18 +++++++++++
   7  fs/ext4/mballoc.c     |    8 ++++-
   8  fs/ext4/page-io.c     |   80 +++++++++++++++++++++++++++++++++++++++++++++++-
   9  fs/jbd2/commit.c      |   18 +++++++++++
  10  fs/jbd2/transaction.c |    5 +++
  11  mm/filemap.c          |    7 ++++
  12  8 files changed, 186 insertions(+), 3 deletions(-)
  13
  14 diff --git a/block/blk-core.c b/block/blk-core.c
  15 index 32a1c12..115574b 100644
  16 --- a/block/blk-core.c
  17 +++ b/block/blk-core.c
  18 @@ -248,6 +248,9 @@ int blk_remove_plug(struct request_queue *q)
  19         if (!queue_flag_test_and_clear(QUEUE_FLAG_PLUGGED, q))
  20                 return 0;
  21
  22 +#if 1                          /* PDEBUG */
  23 +       trace_printk("del timer %s\n", q->backing_dev_info.name);
  24 +#endif
  25         del_timer(&q->unplug_timer);
  26         return 1;
  27  }
  28 @@ -379,6 +382,9 @@ EXPORT_SYMBOL(blk_stop_queue);
  29   */
  30  void blk_sync_queue(struct request_queue *q)
  31  {
  32 +#if 1                          /* PDEBUG */
  33 +       trace_printk("del timer %s\n", q->backing_dev_info.name);
  34 +#endif
  35         del_timer_sync(&q->unplug_timer);
  36         del_timer_sync(&q->timeout);
  37         cancel_work_sync(&q->unplug_work);
  38 @@ -1525,6 +1531,17 @@ static inline void __generic_make_request(struct bio *bio)
  39                 trace_block_bio_queue(q, bio);
  40
  41                 ret = q->make_request_fn(q, bio);
  42 +
  43 +#if 1                          /* PDEBUG */
  44 +               {
  45 +                       char str[KSYM_SYMBOL_LEN];
  46 +
  47 +                       kallsyms_lookup((unsigned long) q->make_request_fn,
  48 +                                       NULL, NULL, NULL, str);
  49 +                       trace_printk("returned from %s (pid %d)\n",
  50 +                                    str, task_pid_nr(current));
  51 +               }
  52 +#endif
  53         } while (ret);
  54
  55         return;
  56 diff --git a/fs/buffer.c b/fs/buffer.c
  57 index 3e7dca2..ed188f5 100644
  58 --- a/fs/buffer.c
  59 +++ b/fs/buffer.c
  60 @@ -70,6 +70,19 @@ static int sync_buffer(void *word)
  61
  62  void __lock_buffer(struct buffer_head *bh)
  63  {
  64 +#if 1                          /* PDEBUG */
  65 +       void *ip = __builtin_return_address(0);
  66 +       char str[KSYM_SYMBOL_LEN];
  67 +       char b[BDEVNAME_SIZE];
  68 +
  69 +       if (buffer_locked(bh)) {
  70 +               kallsyms_lookup((unsigned long) ip, NULL, NULL, NULL, str);
  71 +               trace_printk("lock bh %s blk %lu, ret_pc %p (%s) pid %d\n",
  72 +                            bdevname(bh->b_bdev, b),
  73 +                            (unsigned long) bh->b_blocknr, ip, str,
  74 +                            task_pid_nr(current));
  75 +       }
  76 +#endif
  77         wait_on_bit_lock(&bh->b_state, BH_Lock, sync_buffer,
  78                                                         TASK_UNINTERRUPTIBLE);
  79  }
  80 @@ -90,6 +103,17 @@ EXPORT_SYMBOL(unlock_buffer);
  81   */
  82  void __wait_on_buffer(struct buffer_head * bh)
  83  {
  84 +#if 1                          /* PDEBUG */
  85 +       void *ip = __builtin_return_address(0);
  86 +       char str[KSYM_SYMBOL_LEN];
  87 +       char b[BDEVNAME_SIZE];
  88 +
  89 +       kallsyms_lookup((unsigned long) ip, NULL, NULL, NULL, str);
  90 +       trace_printk("dev %s blk %lu, ret_pc %p (%s) pid %d\n",
  91 +                    bdevname(bh->b_bdev, b),
  92 +                    (unsigned long) bh->b_blocknr, ip, str,
  93 +                    task_pid_nr(current));
  94 +#endif
  95         wait_on_bit(&bh->b_state, BH_Lock, sync_buffer, TASK_UNINTERRUPTIBLE);
  96  }
  97  EXPORT_SYMBOL(__wait_on_buffer);
  98 @@ -2906,6 +2930,18 @@ int submit_bh(int rw, struct buffer_head * bh)
  99         struct bio *bio;
 100         int ret = 0;
 101
 102 +#if 1                          /* PDEBUG */
 103 +       void *ip = __builtin_return_address(0);
 104 +       char str[KSYM_SYMBOL_LEN];
 105 +       char b[BDEVNAME_SIZE];
 106 +
 107 +       kallsyms_lookup((unsigned long) ip, NULL, NULL, NULL, str);
 108 +       trace_printk("dev %s blk %lu, ret_pc %p (%s) pid %d\n",
 109 +                    bdevname(bh->b_bdev, b),
 110 +                    (unsigned long) bh->b_blocknr, ip, str,
 111 +                    task_pid_nr(current));
 112 +#endif
 113 +
 114         BUG_ON(!buffer_locked(bh));
 115         BUG_ON(!buffer_mapped(bh));
 116         BUG_ON(!bh->b_end_io);
 117 diff --git a/fs/ext4/inode.c b/fs/ext4/inode.c
 118 index 79fdace..82eafb9 100644
 119 --- a/fs/ext4/inode.c
 120 +++ b/fs/ext4/inode.c
 121 @@ -2029,6 +2029,11 @@ static int mpage_da_submit_io(struct mpage_da_data *mpd,
 122         index = mpd->first_page;
 123         end = mpd->next_page - 1;
 124
 125 +#if 1                          /* PDEBUG */
 126 +       trace_printk("%s: ino %lu index %lu end %lu size %lu\n",
 127 +                    inode->i_sb->s_id, inode->i_ino,
 128 +                    index, end, (unsigned long) size);
 129 +#endif
 130         pagevec_init(&pvec, 0);
 131         while (index <= end) {
 132                 nr_pages = pagevec_lookup(&pvec, mapping, index, PAGEVEC_SIZE);
 133 @@ -3654,6 +3659,9 @@ int flush_completed_IO(struct inode *inode)
 134         if (list_empty(&ei->i_completed_io_list))
 135                 return ret;
 136
 137 +#if 1                          /* PDEBUG */
 138 +       trace_printk("%s: ino %lu\n", inode->i_sb->s_id, inode->i_ino);
 139 +#endif
 140         dump_completed_IO(inode);
 141         spin_lock_irqsave(&ei->i_completed_io_lock, flags);
 142         while (!list_empty(&ei->i_completed_io_list)){
 143 @@ -3694,6 +3702,16 @@ static void ext4_end_io_dio(struct kiocb *iocb, loff_t offset,
 144         unsigned long flags;
 145         struct ext4_inode_info *ei;
 146
 147 +#if 1                          /* PDEBUG */
 148 +       if (io_end)
 149 +               trace_printk("%s: ino %lu io_end %p size %lu\n",
 150 +                            io_end->inode->i_sb->s_id,
 151 +                            io_end->inode->i_ino, io_end,
 152 +                            (unsigned long) size);
 153 +       else
 154 +               trace_printk("null io_end\n");
 155 +#endif
 156 +
 157         /* if not async direct IO or dio with 0 bytes write, just return */
 158         if (!io_end || !size)
 159                 goto out;
 160 diff --git a/fs/ext4/mballoc.c b/fs/ext4/mballoc.c
 161 index d732ef5..d1b68b7 100644
 162 --- a/fs/ext4/mballoc.c
 163 +++ b/fs/ext4/mballoc.c
 164 @@ -861,8 +861,14 @@ static int ext4_mb_init_cache(struct page *page, char *incore)
 165         }
 166
 167         /* wait for I/O completion */
 168 -       for (i = 0; i < groups_per_page && bh[i]; i++)
 169 +       for (i = 0; i < groups_per_page && bh[i]; i++) {
 170 +#if 1                          /* PDEBUG */
 171 +               if (buffer_locked(bh[i]))
 172 +                       trace_printk("%s: wait on %lu\n", sb->s_id,
 173 +                              (unsigned long) bh[i]->b_blocknr);
 174 +#endif
 175                 wait_on_buffer(bh[i]);
 176 +       }
 177
 178         err = -EIO;
 179         for (i = 0; i < groups_per_page && bh[i]; i++)
 180 diff --git a/fs/ext4/page-io.c b/fs/ext4/page-io.c
 181 index ccce2c6..c2f42e0 100644
 182 --- a/fs/ext4/page-io.c
 183 +++ b/fs/ext4/page-io.c
 184 @@ -30,6 +30,8 @@
 185  #include "acl.h"
 186  #include "ext4_extents.h"
 187
 188 +#define PDEBUG
 189 +
 190  static struct kmem_cache *io_page_cachep, *io_end_cachep;
 191
 192  int __init init_ext4_pageio(void)
 193 @@ -56,6 +58,9 @@ void ext4_free_io_end(ext4_io_end_t *io)
 194  {
 195         int i;
 196
 197 +#ifdef PDEBUG
 198 +       trace_printk("%p\n", io);
 199 +#endif
 200         BUG_ON(!io);
 201         if (io->page)
 202                 put_page(io->page);
 203 @@ -63,6 +68,11 @@ void ext4_free_io_end(ext4_io_end_t *io)
 204                 if (--io->pages[i]->p_count == 0) {
 205                         struct page *page = io->pages[i]->p_page;
 206
 207 +#ifdef PDEBUG
 208 +                       trace_printk("%s: end_page_writeback for %lu:%lu\n",
 209 +                                    io->inode->i_sb->s_id, io->inode->i_ino,
 210 +                                    (unsigned long) page->index);
 211 +#endif
 212                         end_page_writeback(page);
 213                         put_page(page);
 214                         kmem_cache_free(io_page_cachep, io->pages[i]);
 215 @@ -121,6 +131,9 @@ static void ext4_end_io_work(struct work_struct *work)
 216         int                     ret;
 217
 218         mutex_lock(&inode->i_mutex);
 219 +#ifdef PDEBUG
 220 +       trace_printk("%p\n", io);
 221 +#endif
 222         ret = ext4_end_io_nolock(io);
 223         if (ret < 0) {
 224                 mutex_unlock(&inode->i_mutex);
 225 @@ -147,6 +160,9 @@ ext4_io_end_t *ext4_init_io_end(struct inode *inode, gfp_t flags)
 226                 INIT_WORK(&io->work, ext4_end_io_work);
 227                 INIT_LIST_HEAD(&io->list);
 228         }
 229 +#ifdef PDEBUG
 230 +       trace_printk("%p\n", io);
 231 +#endif
 232         return io;
 233  }
 234
 235 @@ -175,6 +191,12 @@ static void ext4_end_bio(struct bio *bio, int error)
 236
 237         BUG_ON(!io_end);
 238         inode = io_end->inode;
 239 +#ifdef PDEBUG
 240 +       trace_printk("%s: enter: ino %lu offset %lu size %ld io_end=%p\n",
 241 +                    inode->i_sb->s_id, inode->i_ino,
 242 +                    (unsigned long) io_end->offset,
 243 +                    (long) io_end->size, io_end);
 244 +#endif
 245         bio->bi_private = NULL;
 246         bio->bi_end_io = NULL;
 247         if (test_bit(BIO_UPTODATE, &bio->bi_flags))
 248 @@ -235,6 +257,12 @@ static void ext4_end_bio(struct bio *bio, int error)
 249                 if (--io_end->pages[i]->p_count == 0) {
 250                         struct page *page = io_end->pages[i]->p_page;
 251
 252 +#ifdef PDEBUG
 253 +                       trace_printk("%s: end_page_writeback for %lu:%lu\n",
 254 +                                    io_end->inode->i_sb->s_id,
 255 +                                    io_end->inode->i_ino,
 256 +                                    (unsigned long) page->index);
 257 +#endif
 258                         end_page_writeback(page);
 259                         put_page(page);
 260                         kmem_cache_free(io_page_cachep, io_end->pages[i]);
 261 @@ -261,12 +289,24 @@ static void ext4_end_bio(struct bio *bio, int error)
 262         wq = EXT4_SB(inode->i_sb)->dio_unwritten_wq;
 263         /* queue the work to convert unwritten extents to written */
 264         queue_work(wq, &io_end->work);
 265 +#ifdef PDEBUG
 266 +       trace_printk("%s: exit: ino %lu\n", inode->i_sb->s_id,
 267 +                    io_end->inode->i_ino);
 268 +#endif
 269  }
 270
 271  void ext4_io_submit(struct ext4_io_submit *io)
 272  {
 273         struct bio *bio = io->io_bio;
 274
 275 +#ifdef PDEBUG
 276 +       if (io->io_end)
 277 +               trace_printk("%s: io submitted io_end %p\n",
 278 +                            io->io_end->inode->i_sb->s_id, io->io_end);
 279 +       else
 280 +               trace_printk("io submitted io_end %p\n",
 281 +                            io->io_end);
 282 +#endif
 283         if (bio) {
 284                 bio_get(io->io_bio);
 285                 submit_bio(io->io_op, io->io_bio);
 286 @@ -308,10 +348,14 @@ static int io_submit_init(struct ext4_io_submit *io,
 287         io->io_op = (wbc->sync_mode == WB_SYNC_ALL ?
 288                         WRITE_SYNC_PLUG : WRITE);
 289         io->io_next_block = bh->b_blocknr;
 290 +#ifdef PDEBUG
 291 +       trace_printk("%s: io_submit_init for ino %lu, nvecs = %d\n",
 292 +                    inode->i_sb->s_id, inode->i_ino, nvecs);
 293 +#endif
 294         return 0;
 295  }
 296
 297 -static int io_submit_add_bh(struct ext4_io_submit *io,
 298 +static noinline int io_submit_add_bh(struct ext4_io_submit *io,
 299                             struct ext4_io_page *io_page,
 300                             struct inode *inode,
 301                             struct writeback_control *wbc,
 302 @@ -320,6 +364,14 @@ static int io_submit_add_bh(struct ext4_io_submit *io,
 303         ext4_io_end_t *io_end;
 304         int ret;
 305
 306 +#ifdef PDEBUG
 307 +       trace_printk("%s enter: ino %lu blk %lu %s%s%s%s\n", inode->i_sb->s_id,
 308 +                    inode->i_ino, (unsigned long) bh->b_blocknr,
 309 +                    buffer_new(bh) ? "N" : "",
 310 +                    buffer_mapped(bh) ? "M" : "",
 311 +                    buffer_delay(bh) ? "D" : "",
 312 +                    buffer_dirty(bh) ? "d" : "");
 313 +#endif
 314         if (buffer_new(bh)) {
 315                 clear_buffer_new(bh);
 316                 unmap_underlying_metadata(bh->b_bdev, bh->b_blocknr);
 317 @@ -351,13 +403,29 @@ submit_and_retry:
 318         io->io_end->size += bh->b_size;
 319         io->io_next_block++;
 320         ret = bio_add_page(io->io_bio, bh->b_page, bh->b_size, bh_offset(bh));
 321 -       if (ret != bh->b_size)
 322 +       if (ret != bh->b_size) {
 323 +#ifdef PDEBUG
 324 +               trace_printk("%s: submit and retry (ret = %d, size=%d, "
 325 +                            "offset=%lu)\n", inode->i_sb->s_id, ret,
 326 +                            bh->b_size, bh_offset(bh));
 327 +#endif
 328                 goto submit_and_retry;
 329 +       }
 330         if ((io_end->num_io_pages == 0) ||
 331             (io_end->pages[io_end->num_io_pages-1] != io_page)) {
 332                 io_end->pages[io_end->num_io_pages++] = io_page;
 333                 io_page->p_count++;
 334         }
 335 +#ifdef PDEBUG
 336 +       if (io->io_end)
 337 +               trace_printk("%s: exit: ino %lu offset %lu size %ld\n",
 338 +                            inode->i_sb->s_id, inode->i_ino,
 339 +                            (unsigned long) io->io_end->offset,
 340 +                            (unsigned long) io->io_end->size);
 341 +       else
 342 +               trace_printk("%s: exit: ino %lu no_io_end\n",
 343 +                            inode->i_sb->s_id, inode->i_ino);
 344 +#endif
 345         return 0;
 346  }
 347
 348 @@ -372,6 +440,10 @@ int ext4_bio_write_page(struct ext4_io_submit *io,
 349         struct buffer_head *bh, *head;
 350         int ret = 0;
 351
 352 +#ifdef PDEBUG
 353 +       trace_printk("%s: enter: ino %lu page %lu len %d\n", inode->i_sb->s_id,
 354 +                    inode->i_ino, page->index, len);
 355 +#endif
 356         blocksize = 1 << inode->i_blkbits;
 357
 358         BUG_ON(PageWriteback(page));
 359 @@ -422,5 +494,9 @@ int ext4_bio_write_page(struct ext4_io_submit *io,
 360                 end_page_writeback(page);
 361                 kmem_cache_free(io_page_cachep, io_page);
 362         }
 363 +#ifdef PDEBUG
 364 +       trace_printk("%s: exit: for ino %lu\n", inode->i_sb->s_id,
 365 +                    inode->i_ino);
 366 +#endif
 367         return ret;
 368  }
 369 diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
 370 index 6494c81..d3f8634 100644
 371 --- a/fs/jbd2/commit.c
 372 +++ b/fs/jbd2/commit.c
 373 @@ -631,6 +631,10 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 374                  * (which is of type BJ_IO)
 375                  */
 376                 JBUFFER_TRACE(jh, "ph3: write metadata");
 377 +#if 1                          /* PDEBUG */
 378 +               trace_printk("@635 %s block %llu\n", journal->j_devname,
 379 +                            blocknr);
 380 +#endif
 381                 flags = jbd2_journal_write_metadata_buffer(commit_transaction,
 382                                                       jh, &new_jh, blocknr);
 383                 if (flags < 0) {
 384 @@ -693,6 +697,11 @@ start_journal_io:
 385                                 clear_buffer_dirty(bh);
 386                                 set_buffer_uptodate(bh);
 387                                 bh->b_end_io = journal_end_buffer_io_sync;
 388 +#if 1                          /* PDEBUG */
 389 +                               trace_printk("@700 %s block %llu\n",
 390 +                                            journal->j_devname,
 391 +                                            bh->b_blocknr);
 392 +#endif
 393                                 submit_bh(write_op, bh);
 394                         }
 395                         cond_resched();
 396 @@ -762,6 +771,10 @@ wait_for_iobuf:
 397                 jh = commit_transaction->t_iobuf_list->b_tprev;
 398                 bh = jh2bh(jh);
 399                 if (buffer_locked(bh)) {
 400 +#if 1                          /* PDEBUG */
 401 +                       trace_printk("jbd wait_on_buffer@765: %lu\n",
 402 +                                    (unsigned long) bh->b_blocknr);
 403 +#endif
 404                         wait_on_buffer(bh);
 405                         goto wait_for_iobuf;
 406                 }
 407 @@ -818,6 +831,11 @@ wait_for_iobuf:
 408                 jh = commit_transaction->t_log_list->b_tprev;
 409                 bh = jh2bh(jh);
 410                 if (buffer_locked(bh)) {
 411 +#if 1                          /* PDEBUG */
 412 +                       trace_printk("%s: jbd wait_on_buffer@823: %lu\n",
 413 +                                    journal->j_devname,
 414 +                                    (unsigned long) bh->b_blocknr);
 415 +#endif
 416                         wait_on_buffer(bh);
 417                         goto wait_for_ctlbuf;
 418                 }
 419 diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
 420 index 6bf0a24..8873caa 100644
 421 --- a/fs/jbd2/transaction.c
 422 +++ b/fs/jbd2/transaction.c
 423 @@ -701,6 +701,11 @@ repeat:
 424                         for ( ; ; ) {
 425                                 prepare_to_wait(wqh, &wait.wait,
 426                                                 TASK_UNINTERRUPTIBLE);
 427 +#if 1                          /* PDEBUG */
 428 +                               trace_printk("%s: BJ shadow waiting on %lu\n",
 429 +                                      journal->j_devname,
 430 +                                      (unsigned long) bh->b_blocknr);
 431 +#endif
 432                                 if (jh->b_jlist != BJ_Shadow)
 433                                         break;
 434                                 schedule();
 435 diff --git a/mm/filemap.c b/mm/filemap.c
 436 index 3d4df44..e0c7061 100644
 437 --- a/mm/filemap.c
 438 +++ b/mm/filemap.c
 439 @@ -295,6 +295,13 @@ int filemap_fdatawait_range(struct address_space *mapping, loff_t start_byte,
 440                         if (page->index > end)
 441                                 continue;
 442
 443 +#if 1                          /* PDEBUG */
 444 +                       if (PageWriteback(page))
 445 +                               trace_printk("pid %d waiting on %lu:%lu\n",
 446 +                                            task_pid_nr(current),
 447 +                                            mapping->host->i_ino,
 448 +                                            (unsigned long) page->index);
 449 +#endif
 450                         wait_on_page_writeback(page);
 451                         if (PageError(page))
 452                                 ret = -EIO;