f2fs: add time stats of checkpoint for debug

+68

2 changed files

expand all

f2fs

checkpoint.c

f2fs.h

+46

fs/f2fs/checkpoint.c

··· 1442 1442 return get_sectors_written(sbi->sb->s_bdev); 1443 1443 } 1444 1444 1445 + static inline void stat_cp_time(struct cp_control *cpc, enum cp_time type) 1446 + { 1447 + cpc->stats.times[type] = ktime_get(); 1448 + } 1449 + 1450 + static inline void check_cp_time(struct f2fs_sb_info *sbi, struct cp_control *cpc) 1451 + { 1452 + unsigned long long sb_diff, cur_diff; 1453 + enum cp_time ct; 1454 + 1455 + sb_diff = (u64)ktime_ms_delta(sbi->cp_stats.times[CP_TIME_END], 1456 + sbi->cp_stats.times[CP_TIME_START]); 1457 + cur_diff = (u64)ktime_ms_delta(cpc->stats.times[CP_TIME_END], 1458 + cpc->stats.times[CP_TIME_START]); 1459 + 1460 + if (cur_diff > sb_diff) { 1461 + sbi->cp_stats = cpc->stats; 1462 + if (cur_diff < CP_LONG_LATENCY_THRESHOLD) 1463 + return; 1464 + 1465 + f2fs_warn(sbi, "checkpoint was blocked for %llu ms", cur_diff); 1466 + for (ct = CP_TIME_START; ct < CP_TIME_MAX - 1; ct++) 1467 + f2fs_warn(sbi, "Step#%d: %llu ms", ct, 1468 + (u64)ktime_ms_delta(cpc->stats.times[ct + 1], 1469 + cpc->stats.times[ct])); 1470 + } 1471 + } 1472 + 1445 1473 static int do_checkpoint(struct f2fs_sb_info *sbi, struct cp_control *cpc) 1446 1474 { 1447 1475 struct f2fs_checkpoint *ckpt = F2FS_CKPT(sbi); ··· 1486 1458 1487 1459 /* Flush all the NAT/SIT pages */ 1488 1460 f2fs_sync_meta_pages(sbi, META, LONG_MAX, FS_CP_META_IO); 1461 + 1462 + stat_cp_time(cpc, CP_TIME_SYNC_META); 1489 1463 1490 1464 /* start to update checkpoint, cp ver is already updated previously */ 1491 1465 ckpt->elapsed_time = cpu_to_le64(get_mtime(sbi, true)); ··· 1585 1555 1586 1556 /* Here, we have one bio having CP pack except cp pack 2 page */ 1587 1557 f2fs_sync_meta_pages(sbi, META, LONG_MAX, FS_CP_META_IO); 1558 + stat_cp_time(cpc, CP_TIME_SYNC_CP_META); 1559 + 1588 1560 /* Wait for all dirty meta pages to be submitted for IO */ 1589 1561 f2fs_wait_on_all_pages(sbi, F2FS_DIRTY_META); 1562 + stat_cp_time(cpc, CP_TIME_WAIT_DIRTY_META); 1590 1563 1591 1564 /* wait for previous submitted meta pages writeback */ 1592 1565 f2fs_wait_on_all_pages(sbi, F2FS_WB_CP_DATA); 1566 + stat_cp_time(cpc, CP_TIME_WAIT_CP_DATA); 1593 1567 1594 1568 /* flush all device cache */ 1595 1569 err = f2fs_flush_device_cache(sbi); 1596 1570 if (err) 1597 1571 return err; 1572 + stat_cp_time(cpc, CP_TIME_FLUSH_DEVICE); 1598 1573 1599 1574 /* barrier and flush checkpoint cp pack 2 page if it can */ 1600 1575 commit_checkpoint(sbi, ckpt, start_blk); 1601 1576 f2fs_wait_on_all_pages(sbi, F2FS_WB_CP_DATA); 1577 + stat_cp_time(cpc, CP_TIME_WAIT_LAST_CP); 1602 1578 1603 1579 /* 1604 1580 * invalidate intermediate page cache borrowed from meta inode which are ··· 1649 1613 unsigned long long ckpt_ver; 1650 1614 int err = 0; 1651 1615 1616 + stat_cp_time(cpc, CP_TIME_START); 1617 + 1652 1618 if (f2fs_readonly(sbi->sb) || f2fs_hw_is_readonly(sbi)) 1653 1619 return -EROFS; 1654 1620 ··· 1661 1623 } 1662 1624 if (cpc->reason != CP_RESIZE) 1663 1625 f2fs_down_write(&sbi->cp_global_sem); 1626 + 1627 + stat_cp_time(cpc, CP_TIME_LOCK); 1664 1628 1665 1629 if (!is_sbi_flag_set(sbi, SBI_IS_DIRTY) && 1666 1630 ((cpc->reason & CP_FASTBOOT) || (cpc->reason & CP_SYNC) || ··· 1678 1638 err = block_operations(sbi); 1679 1639 if (err) 1680 1640 goto out; 1641 + 1642 + stat_cp_time(cpc, CP_TIME_OP_LOCK); 1681 1643 1682 1644 trace_f2fs_write_checkpoint(sbi->sb, cpc->reason, "finish block_ops"); 1683 1645 ··· 1720 1678 1721 1679 f2fs_flush_sit_entries(sbi, cpc); 1722 1680 1681 + stat_cp_time(cpc, CP_TIME_FLUSH_META); 1682 + 1723 1683 /* save inmem log status */ 1724 1684 f2fs_save_inmem_curseg(sbi); 1725 1685 ··· 1739 1695 stat_inc_cp_count(sbi); 1740 1696 stop: 1741 1697 unblock_operations(sbi); 1698 + stat_cp_time(cpc, CP_TIME_END); 1699 + check_cp_time(sbi, cpc); 1742 1700 1743 1701 if (cpc->reason & CP_RECOVERY) 1744 1702 f2fs_notice(sbi, "checkpoint: version = %llx", ckpt_ver);

+22

fs/f2fs/f2fs.h

··· 269 269 #define DEF_DISABLE_QUICK_INTERVAL 1 /* 1 secs */ 270 270 #define DEF_UMOUNT_DISCARD_TIMEOUT 5 /* 5 secs */ 271 271 272 + enum cp_time { 273 + CP_TIME_START, /* begin */ 274 + CP_TIME_LOCK, /* after cp_global_sem */ 275 + CP_TIME_OP_LOCK, /* after block_operation */ 276 + CP_TIME_FLUSH_META, /* after flush sit/nat */ 277 + CP_TIME_SYNC_META, /* after sync_meta_pages */ 278 + CP_TIME_SYNC_CP_META, /* after sync cp meta pages */ 279 + CP_TIME_WAIT_DIRTY_META,/* after wait on dirty meta */ 280 + CP_TIME_WAIT_CP_DATA, /* after wait on cp data */ 281 + CP_TIME_FLUSH_DEVICE, /* after flush device cache */ 282 + CP_TIME_WAIT_LAST_CP, /* after wait on last cp pack */ 283 + CP_TIME_END, /* after unblock_operation */ 284 + CP_TIME_MAX, 285 + }; 286 + 287 + /* time cost stats of checkpoint */ 288 + struct cp_stats { 289 + ktime_t times[CP_TIME_MAX]; 290 + }; 291 + 272 292 struct cp_control { 273 293 int reason; 274 294 __u64 trim_start; 275 295 __u64 trim_end; 276 296 __u64 trim_minlen; 297 + struct cp_stats stats; 277 298 }; 278 299 279 300 /* ··· 1664 1643 unsigned long last_time[MAX_TIME]; /* to store time in jiffies */ 1665 1644 long interval_time[MAX_TIME]; /* to store thresholds */ 1666 1645 struct ckpt_req_control cprc_info; /* for checkpoint request control */ 1646 + struct cp_stats cp_stats; /* for time stat of checkpoint */ 1667 1647 1668 1648 struct inode_management im[MAX_INO_ENTRY]; /* manage inode cache */ 1669 1649

Configure Feed

Configure Feed