Commit ba80b1019aa722b24506db1ee755e0bb2f513022

Authored by Theodore Ts'o
1 parent c319106723

ext4: Add markers for better debuggability

Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>

Showing 3 changed files with 116 additions and 3 deletions Side-by-side Diff

... ... @@ -210,6 +210,11 @@
210 210  
211 211 ino = inode->i_ino;
212 212 ext4_debug("freeing inode %lu\n", ino);
  213 + trace_mark(ext4_free_inode,
  214 + "dev %s ino %lu mode %d uid %lu gid %lu bocks %llu",
  215 + sb->s_id, inode->i_ino, inode->i_mode,
  216 + (unsigned long) inode->i_uid, (unsigned long) inode->i_gid,
  217 + (unsigned long long) inode->i_blocks);
213 218  
214 219 /*
215 220 * Note: we must free any quota before locking the superblock,
... ... @@ -698,6 +703,8 @@
698 703 return ERR_PTR(-EPERM);
699 704  
700 705 sb = dir->i_sb;
  706 + trace_mark(ext4_request_inode, "dev %s dir %lu mode %d", sb->s_id,
  707 + dir->i_ino, mode);
701 708 inode = new_inode(sb);
702 709 if (!inode)
703 710 return ERR_PTR(-ENOMEM);
... ... @@ -925,6 +932,8 @@
925 932 }
926 933  
927 934 ext4_debug("allocating inode %lu\n", inode->i_ino);
  935 + trace_mark(ext4_allocate_inode, "dev %s ino %lu dir %lu mode %d",
  936 + sb->s_id, inode->i_ino, dir->i_ino, mode);
928 937 goto really_out;
929 938 fail:
930 939 ext4_std_error(sb, err);
... ... @@ -1351,6 +1351,10 @@
1351 1351 pgoff_t index;
1352 1352 unsigned from, to;
1353 1353  
  1354 + trace_mark(ext4_write_begin,
  1355 + "dev %s ino %lu pos %llu len %u flags %u",
  1356 + inode->i_sb->s_id, inode->i_ino,
  1357 + (unsigned long long) pos, len, flags);
1354 1358 index = pos >> PAGE_CACHE_SHIFT;
1355 1359 from = pos & (PAGE_CACHE_SIZE - 1);
1356 1360 to = from + len;
... ... @@ -1422,6 +1426,10 @@
1422 1426 struct inode *inode = mapping->host;
1423 1427 int ret = 0, ret2;
1424 1428  
  1429 + trace_mark(ext4_ordered_write_end,
  1430 + "dev %s ino %lu pos %llu len %u copied %u",
  1431 + inode->i_sb->s_id, inode->i_ino,
  1432 + (unsigned long long) pos, len, copied);
1425 1433 ret = ext4_jbd2_file_inode(handle, inode);
1426 1434  
1427 1435 if (ret == 0) {
... ... @@ -1460,6 +1468,10 @@
1460 1468 int ret = 0, ret2;
1461 1469 loff_t new_i_size;
1462 1470  
  1471 + trace_mark(ext4_writeback_write_end,
  1472 + "dev %s ino %lu pos %llu len %u copied %u",
  1473 + inode->i_sb->s_id, inode->i_ino,
  1474 + (unsigned long long) pos, len, copied);
1463 1475 new_i_size = pos + copied;
1464 1476 if (new_i_size > EXT4_I(inode)->i_disksize) {
1465 1477 ext4_update_i_disksize(inode, new_i_size);
... ... @@ -1495,6 +1507,10 @@
1495 1507 unsigned from, to;
1496 1508 loff_t new_i_size;
1497 1509  
  1510 + trace_mark(ext4_journalled_write_end,
  1511 + "dev %s ino %lu pos %llu len %u copied %u",
  1512 + inode->i_sb->s_id, inode->i_ino,
  1513 + (unsigned long long) pos, len, copied);
1498 1514 from = pos & (PAGE_CACHE_SIZE - 1);
1499 1515 to = from + len;
1500 1516  
... ... @@ -2311,6 +2327,9 @@
2311 2327 struct buffer_head *page_bufs;
2312 2328 struct inode *inode = page->mapping->host;
2313 2329  
  2330 + trace_mark(ext4_da_writepage,
  2331 + "dev %s ino %lu page_index %lu",
  2332 + inode->i_sb->s_id, inode->i_ino, page->index);
2314 2333 size = i_size_read(inode);
2315 2334 if (page->index == size >> PAGE_CACHE_SHIFT)
2316 2335 len = size & ~PAGE_CACHE_MASK;
... ... @@ -2421,6 +2440,20 @@
2421 2440 int needed_blocks, ret = 0, nr_to_writebump = 0;
2422 2441 struct ext4_sb_info *sbi = EXT4_SB(mapping->host->i_sb);
2423 2442  
  2443 + trace_mark(ext4_da_writepages,
  2444 + "dev %s ino %lu nr_t_write %ld "
  2445 + "pages_skipped %ld range_start %llu "
  2446 + "range_end %llu nonblocking %d "
  2447 + "for_kupdate %d for_reclaim %d "
  2448 + "for_writepages %d range_cyclic %d",
  2449 + inode->i_sb->s_id, inode->i_ino,
  2450 + wbc->nr_to_write, wbc->pages_skipped,
  2451 + (unsigned long long) wbc->range_start,
  2452 + (unsigned long long) wbc->range_end,
  2453 + wbc->nonblocking, wbc->for_kupdate,
  2454 + wbc->for_reclaim, wbc->for_writepages,
  2455 + wbc->range_cyclic);
  2456 +
2424 2457 /*
2425 2458 * No pages to write? This is mainly a kludge to avoid starting
2426 2459 * a transaction for special inodes like journal inode on last iput()
... ... @@ -2539,6 +2572,14 @@
2539 2572 if (!no_nrwrite_index_update)
2540 2573 wbc->no_nrwrite_index_update = 0;
2541 2574 wbc->nr_to_write -= nr_to_writebump;
  2575 + trace_mark(ext4_da_writepage_result,
  2576 + "dev %s ino %lu ret %d pages_written %d "
  2577 + "pages_skipped %ld congestion %d "
  2578 + "more_io %d no_nrwrite_index_update %d",
  2579 + inode->i_sb->s_id, inode->i_ino, ret,
  2580 + pages_written, wbc->pages_skipped,
  2581 + wbc->encountered_congestion, wbc->more_io,
  2582 + wbc->no_nrwrite_index_update);
2542 2583 return ret;
2543 2584 }
2544 2585  
... ... @@ -2590,6 +2631,11 @@
2590 2631 len, flags, pagep, fsdata);
2591 2632 }
2592 2633 *fsdata = (void *)0;
  2634 +
  2635 + trace_mark(ext4_da_write_begin,
  2636 + "dev %s ino %lu pos %llu len %u flags %u",
  2637 + inode->i_sb->s_id, inode->i_ino,
  2638 + (unsigned long long) pos, len, flags);
2593 2639 retry:
2594 2640 /*
2595 2641 * With delayed allocation, we don't log the i_disksize update
... ... @@ -2679,6 +2725,10 @@
2679 2725 }
2680 2726 }
2681 2727  
  2728 + trace_mark(ext4_da_write_end,
  2729 + "dev %s ino %lu pos %llu len %u copied %u",
  2730 + inode->i_sb->s_id, inode->i_ino,
  2731 + (unsigned long long) pos, len, copied);
2682 2732 start = pos & (PAGE_CACHE_SIZE - 1);
2683 2733 end = start + copied - 1;
2684 2734  
... ... @@ -2892,6 +2942,9 @@
2892 2942 loff_t size = i_size_read(inode);
2893 2943 loff_t len;
2894 2944  
  2945 + trace_mark(ext4_normal_writepage,
  2946 + "dev %s ino %lu page_index %lu",
  2947 + inode->i_sb->s_id, inode->i_ino, page->index);
2895 2948 J_ASSERT(PageLocked(page));
2896 2949 if (page->index == size >> PAGE_CACHE_SHIFT)
2897 2950 len = size & ~PAGE_CACHE_MASK;
... ... @@ -2977,6 +3030,9 @@
2977 3030 loff_t size = i_size_read(inode);
2978 3031 loff_t len;
2979 3032  
  3033 + trace_mark(ext4_journalled_writepage,
  3034 + "dev %s ino %lu page_index %lu",
  3035 + inode->i_sb->s_id, inode->i_ino, page->index);
2980 3036 J_ASSERT(PageLocked(page));
2981 3037 if (page->index == size >> PAGE_CACHE_SHIFT)
2982 3038 len = size & ~PAGE_CACHE_MASK;
... ... @@ -2878,8 +2878,9 @@
2878 2878 discard_block = (ext4_fsblk_t) entry->group * EXT4_BLOCKS_PER_GROUP(sb)
2879 2879 + entry->start_blk
2880 2880 + le32_to_cpu(EXT4_SB(sb)->s_es->s_first_data_block);
2881   - trace_mark(ext4_discard_blocks, "dev %s blk %llu count %u", sb->s_id,
2882   - (unsigned long long) discard_block, entry->count);
  2881 + trace_mark(ext4_discard_blocks, "dev %s blk %llu count %u",
  2882 + sb->s_id, (unsigned long long) discard_block,
  2883 + entry->count);
2883 2884 sb_issue_discard(sb, discard_block, entry->count);
2884 2885  
2885 2886 kmem_cache_free(ext4_free_ext_cachep, entry);
... ... @@ -3697,6 +3698,10 @@
3697 3698  
3698 3699 mb_debug("new inode pa %p: %llu/%u for %u\n", pa,
3699 3700 pa->pa_pstart, pa->pa_len, pa->pa_lstart);
  3701 + trace_mark(ext4_mb_new_inode_pa,
  3702 + "dev %s ino %lu pstart %llu len %u lstart %u",
  3703 + sb->s_id, ac->ac_inode->i_ino,
  3704 + pa->pa_pstart, pa->pa_len, pa->pa_lstart);
3700 3705  
3701 3706 ext4_mb_use_inode_pa(ac, pa);
3702 3707 atomic_add(pa->pa_free, &EXT4_SB(sb)->s_mb_preallocated);
... ... @@ -3754,7 +3759,9 @@
3754 3759 pa->pa_linear = 1;
3755 3760  
3756 3761 mb_debug("new group pa %p: %llu/%u for %u\n", pa,
3757   - pa->pa_pstart, pa->pa_len, pa->pa_lstart);
  3762 + pa->pa_pstart, pa->pa_len, pa->pa_lstart);
  3763 + trace_mark(ext4_mb_new_group_pa, "dev %s pstart %llu len %u lstart %u",
  3764 + sb->s_id, pa->pa_pstart, pa->pa_len, pa->pa_lstart);
3758 3765  
3759 3766 ext4_mb_use_group_pa(ac, pa);
3760 3767 atomic_add(pa->pa_free, &EXT4_SB(sb)->s_mb_preallocated);
3761 3768  
... ... @@ -3807,12 +3814,14 @@
3807 3814 unsigned int next;
3808 3815 ext4_group_t group;
3809 3816 ext4_grpblk_t bit;
  3817 + unsigned long long grp_blk_start;
3810 3818 sector_t start;
3811 3819 int err = 0;
3812 3820 int free = 0;
3813 3821  
3814 3822 BUG_ON(pa->pa_deleted == 0);
3815 3823 ext4_get_group_no_and_offset(sb, pa->pa_pstart, &group, &bit);
  3824 + grp_blk_start = pa->pa_pstart - bit;
3816 3825 BUG_ON(group != e4b->bd_group && pa->pa_len != 0);
3817 3826 end = bit + pa->pa_len;
3818 3827  
... ... @@ -3842,6 +3851,10 @@
3842 3851 ext4_mb_store_history(ac);
3843 3852 }
3844 3853  
  3854 + trace_mark(ext4_mb_release_inode_pa,
  3855 + "dev %s ino %lu block %llu count %u",
  3856 + sb->s_id, pa->pa_inode->i_ino, grp_blk_start + bit,
  3857 + next - bit);
3845 3858 mb_free_blocks(pa->pa_inode, e4b, bit, next - bit);
3846 3859 bit = next + 1;
3847 3860 }
... ... @@ -3875,6 +3888,8 @@
3875 3888 if (ac)
3876 3889 ac->ac_op = EXT4_MB_HISTORY_DISCARD;
3877 3890  
  3891 + trace_mark(ext4_mb_release_group_pa, "dev %s pstart %llu len %d",
  3892 + sb->s_id, pa->pa_pstart, pa->pa_len);
3878 3893 BUG_ON(pa->pa_deleted == 0);
3879 3894 ext4_get_group_no_and_offset(sb, pa->pa_pstart, &group, &bit);
3880 3895 BUG_ON(group != e4b->bd_group && pa->pa_len != 0);
... ... @@ -4040,6 +4055,8 @@
4040 4055 }
4041 4056  
4042 4057 mb_debug("discard preallocation for inode %lu\n", inode->i_ino);
  4058 + trace_mark(ext4_discard_preallocations, "dev %s ino %lu", sb->s_id,
  4059 + inode->i_ino);
4043 4060  
4044 4061 INIT_LIST_HEAD(&list);
4045 4062  
... ... @@ -4492,6 +4509,8 @@
4492 4509 int ret;
4493 4510 int freed = 0;
4494 4511  
  4512 + trace_mark(ext4_mb_discard_preallocations, "dev %s needed %d",
  4513 + sb->s_id, needed);
4495 4514 for (i = 0; i < EXT4_SB(sb)->s_groups_count && needed > 0; i++) {
4496 4515 ret = ext4_mb_discard_group_preallocations(sb, i, needed);
4497 4516 freed += ret;
... ... @@ -4520,6 +4539,18 @@
4520 4539 sb = ar->inode->i_sb;
4521 4540 sbi = EXT4_SB(sb);
4522 4541  
  4542 + trace_mark(ext4_request_blocks, "dev %s flags %u len %u ino %lu "
  4543 + "lblk %llu goal %llu lleft %llu lright %llu "
  4544 + "pleft %llu pright %llu ",
  4545 + sb->s_id, ar->flags, ar->len,
  4546 + ar->inode ? ar->inode->i_ino : 0,
  4547 + (unsigned long long) ar->logical,
  4548 + (unsigned long long) ar->goal,
  4549 + (unsigned long long) ar->lleft,
  4550 + (unsigned long long) ar->lright,
  4551 + (unsigned long long) ar->pleft,
  4552 + (unsigned long long) ar->pright);
  4553 +
4523 4554 if (!EXT4_I(ar->inode)->i_delalloc_reserved_flag) {
4524 4555 /*
4525 4556 * With delalloc we already reserved the blocks
... ... @@ -4622,6 +4653,19 @@
4622 4653 reserv_blks);
4623 4654 }
4624 4655  
  4656 + trace_mark(ext4_allocate_blocks,
  4657 + "dev %s block %llu flags %u len %u ino %lu "
  4658 + "logical %llu goal %llu lleft %llu lright %llu "
  4659 + "pleft %llu pright %llu ",
  4660 + sb->s_id, (unsigned long long) block,
  4661 + ar->flags, ar->len, ar->inode ? ar->inode->i_ino : 0,
  4662 + (unsigned long long) ar->logical,
  4663 + (unsigned long long) ar->goal,
  4664 + (unsigned long long) ar->lleft,
  4665 + (unsigned long long) ar->lright,
  4666 + (unsigned long long) ar->pleft,
  4667 + (unsigned long long) ar->pright);
  4668 +
4625 4669 return block;
4626 4670 }
4627 4671  
... ... @@ -4755,6 +4799,10 @@
4755 4799 }
4756 4800  
4757 4801 ext4_debug("freeing block %lu\n", block);
  4802 + trace_mark(ext4_free_blocks,
  4803 + "dev %s block %llu count %lu metadata %d ino %lu",
  4804 + sb->s_id, (unsigned long long) block, count, metadata,
  4805 + inode ? inode->i_ino : 0);
4758 4806  
4759 4807 ac = kmem_cache_alloc(ext4_ac_cachep, GFP_NOFS);
4760 4808 if (ac) {