diff --git a/module/zfs/dbuf.c b/module/zfs/dbuf.c index 9ce091b80dcb..d2dc5ed4c49b 100644 --- a/module/zfs/dbuf.c +++ b/module/zfs/dbuf.c @@ -1425,8 +1425,11 @@ dbuf_read_verify_dnode_crypt(dmu_buf_impl_t *db, uint32_t flags) ASSERT(MUTEX_HELD(&db->db_mtx)); if (!os->os_encrypted || os->os_raw_receive || - (flags & DB_RF_NO_DECRYPT) != 0) + (flags & DB_RF_NO_DECRYPT) != 0) { + TraceEvent(8, "%s:%d: Returning 0\n", + __func__, __LINE__); return (0); + } DB_DNODE_ENTER(db); dn = DB_DNODE(db); @@ -1434,12 +1437,16 @@ dbuf_read_verify_dnode_crypt(dmu_buf_impl_t *db, uint32_t flags) if (dnode_abuf == NULL || !arc_is_encrypted(dnode_abuf)) { DB_DNODE_EXIT(db); + TraceEvent(8, "%s:%d: Returning 0\n", + __func__, __LINE__); return (0); } SET_BOOKMARK(&zb, dmu_objset_id(os), DMU_META_DNODE_OBJECT, 0, dn->dn_dbuf->db_blkid); err = arc_untransform(dnode_abuf, os->os_spa, &zb, B_TRUE); + dprintf("%s:%d: Setting err = %d from arc_untransform\n", + __func__, __LINE__, err); /* * An error code of EACCES tells us that the key is still not @@ -1454,6 +1461,12 @@ dbuf_read_verify_dnode_crypt(dmu_buf_impl_t *db, uint32_t flags) DB_DNODE_EXIT(db); + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", + __func__, __LINE__, err); + return (err); } @@ -1554,6 +1567,13 @@ dbuf_read_impl(dmu_buf_impl_t *db, zio_t *zio, uint32_t flags, DB_DNODE_EXIT(db); mutex_exit(&db->db_mtx); dmu_buf_unlock_parent(db, dblt, tag); + + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, + err); + return (err); } @@ -1642,6 +1662,9 @@ dbuf_read(dmu_buf_impl_t *db, zio_t *zio, uint32_t flags) boolean_t prefetch; dnode_t *dn; + TraceEvent(8, "%s:%d: db = 0x%p, zio = 0x%p, flags = %d\n", + __func__, __LINE__, db, zio, flags); + /* * We don't have to hold the mutex to check db_state because it * can't be freed while we have a hold on the buffer. @@ -1686,6 +1709,8 @@ dbuf_read(dmu_buf_impl_t *db, zio_t *zio, uint32_t flags) db->db.db_object, db->db_level, db->db_blkid); dbuf_fix_old_data(db, spa_syncing_txg(spa)); err = arc_untransform(db->db_buf, spa, &zb, B_FALSE); + dprintf("%s:%d: Setting err = %d from " + "arc_untransform\n", __func__, __LINE__, err); dbuf_set_data(db, db->db_buf); } mutex_exit(&db->db_mtx); @@ -1761,10 +1786,17 @@ dbuf_read(dmu_buf_impl_t *db, zio_t *zio, uint32_t flags) } if (db->db_state == DB_UNCACHED) err = SET_ERROR(EIO); + mutex_exit(&db->db_mtx); } } + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", + __func__, __LINE__, err); + return (err); } @@ -2909,6 +2941,10 @@ dbuf_findbp(dnode_t *dn, int level, uint64_t blkid, int fail_sparse, *parentp = NULL; *bpp = NULL; + TraceEvent(8, "%s:%d: dn = 0x%p, level = %d, blkid = %llu," + " fail_sparse = %d\n", __func__, __LINE__, + dn, level, blkid, fail_sparse); + ASSERT(blkid != DMU_BONUS_BLKID); if (blkid == DMU_SPILL_BLKID) { @@ -2921,6 +2957,7 @@ dbuf_findbp(dnode_t *dn, int level, uint64_t blkid, int fail_sparse, dbuf_add_ref(dn->dn_dbuf, NULL); *parentp = dn->dn_dbuf; mutex_exit(&dn->dn_mtx); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -2954,6 +2991,8 @@ dbuf_findbp(dnode_t *dn, int level, uint64_t blkid, int fail_sparse, (fail_sparse && blkid > (dn->dn_phys->dn_maxblkid >> (level * epbs)))) { /* the buffer has no parent yet */ + TraceEvent(5, "%s:%d: Returning ENOENT = %d\n", + __func__, __LINE__, ENOENT); return (SET_ERROR(ENOENT)); } else if (level < nlevels-1) { /* this block is referenced from an indirect block */ @@ -2962,13 +3001,18 @@ dbuf_findbp(dnode_t *dn, int level, uint64_t blkid, int fail_sparse, err = dbuf_hold_impl(dn, level + 1, blkid >> epbs, fail_sparse, FALSE, NULL, parentp); - if (err) + if (err) { + dprintf("%s:%d: Returning %d\n", + __func__, __LINE__, err); return (err); + } err = dbuf_read(*parentp, NULL, (DB_RF_HAVESTRUCT | DB_RF_NOPREFETCH | DB_RF_CANFAIL)); if (err) { dbuf_rele(*parentp, NULL); *parentp = NULL; + dprintf("%s:%d: Returning %d\n", __func__, + __LINE__, err); return (err); } rw_enter(&(*parentp)->db_rwlock, RW_READER); @@ -2977,6 +3021,8 @@ dbuf_findbp(dnode_t *dn, int level, uint64_t blkid, int fail_sparse, if (blkid > (dn->dn_phys->dn_maxblkid >> (level * epbs))) ASSERT(BP_IS_HOLE(*bpp)); rw_exit(&(*parentp)->db_rwlock); + TraceEvent(8, "%s:%d: Returning 0\n", + __func__, __LINE__); return (0); } else { /* the block is referenced from the dnode */ @@ -2988,6 +3034,7 @@ dbuf_findbp(dnode_t *dn, int level, uint64_t blkid, int fail_sparse, *parentp = dn->dn_dbuf; } *bpp = &dn->dn_phys->dn_blkptr[blkid]; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } } @@ -3490,8 +3537,12 @@ dbuf_hold_impl(dnode_t *dn, uint8_t level, uint64_t blkid, blkptr_t *bp = NULL; int err; - if (fail_uncached) + if (fail_uncached) { + TraceEvent(5, "%s:%d: ail_uncached = %d." + " Returning ENOENT = %d\n", + __func__, __LINE__, fail_uncached, ENOENT); return (SET_ERROR(ENOENT)); + } ASSERT3P(parent, ==, NULL); err = dbuf_findbp(dn, level, blkid, fail_sparse, &parent, &bp); @@ -3501,11 +3552,16 @@ dbuf_hold_impl(dnode_t *dn, uint8_t level, uint64_t blkid, if (err) { if (parent) dbuf_rele(parent, NULL); + dprintf("%s:%d: Returning %d\n", + __func__, __LINE__, err); return (err); } } - if (err && err != ENOENT) + if (err && err != ENOENT) { + dprintf("%s:%d: Returning %d\n", __func__, + __LINE__, err); return (err); + } db = dbuf_create(dn, level, blkid, parent, bp); } @@ -3567,6 +3623,7 @@ dbuf_hold_impl(dnode_t *dn, uint8_t level, uint64_t blkid, ASSERT3U(db->db_level, ==, level); *dbp = db; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } diff --git a/module/zfs/dmu.c b/module/zfs/dmu.c index 1c47430953b1..e85650775e07 100644 --- a/module/zfs/dmu.c +++ b/module/zfs/dmu.c @@ -172,6 +172,7 @@ dmu_buf_hold_noread_by_dnode(dnode_t *dn, uint64_t offset, } *dbp = &db->db; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } int @@ -184,8 +185,10 @@ dmu_buf_hold_noread(objset_t *os, uint64_t object, uint64_t offset, int err; err = dnode_hold(os, object, FTAG, &dn); - if (err) + if (err) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } rw_enter(&dn->dn_struct_rwlock, RW_READER); blkid = dbuf_whichblock(dn, 0, offset); db = dbuf_hold(dn, blkid, tag); @@ -198,6 +201,12 @@ dmu_buf_hold_noread(objset_t *os, uint64_t object, uint64_t offset, } *dbp = &db->db; + + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, + __LINE__, err); return (err); } @@ -208,6 +217,9 @@ dmu_buf_hold_by_dnode(dnode_t *dn, uint64_t offset, int err; int db_flags = DB_RF_CANFAIL; + TraceEvent(8, "%s:%d: dn = 0x%p, offset = %llu, tag = 0x%p, " + "dbp = 0x%p, flags = %d\n", __func__, __LINE__, + dn, offset, tag, dbp, flags); if (flags & DMU_READ_NO_PREFETCH) db_flags |= DB_RF_NOPREFETCH; if (flags & DMU_READ_NO_DECRYPT) @@ -223,6 +235,12 @@ dmu_buf_hold_by_dnode(dnode_t *dn, uint64_t offset, } } + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, + __LINE__, err); + return (err); } @@ -248,6 +266,12 @@ dmu_buf_hold(objset_t *os, uint64_t object, uint64_t offset, } } + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, + __LINE__, err); + return (err); } @@ -377,10 +401,13 @@ int dmu_bonus_hold_by_dnode(dnode_t *dn, void *tag, dmu_buf_t **dbp, dnode_evict_bonus(dn); dbuf_rele(db, tag); *dbp = NULL; + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } *dbp = &db->db; + + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -391,12 +418,16 @@ dmu_bonus_hold(objset_t *os, uint64_t object, void *tag, dmu_buf_t **dbp) int error; error = dnode_hold(os, object, FTAG, &dn); - if (error) + if (error) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); + } error = dmu_bonus_hold_by_dnode(dn, tag, dbp, DMU_READ_NO_PREFETCH); dnode_rele(dn, FTAG); + if (error) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1870,10 +1901,15 @@ dmu_object_set_blocksize(objset_t *os, uint64_t object, uint64_t size, int ibs, int err; err = dnode_hold(os, object, FTAG, &dn); - if (err) + if (err) { + dprintf("%s:%d: Returning error %d\n", __func__, __LINE__, + err); return (err); + } err = dnode_set_blksz(dn, size, ibs, tx); dnode_rele(dn, FTAG); + + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } diff --git a/module/zfs/dmu_object.c b/module/zfs/dmu_object.c index 12cdbd68b104..8331325a75f7 100644 --- a/module/zfs/dmu_object.c +++ b/module/zfs/dmu_object.c @@ -288,14 +288,18 @@ dmu_object_claim_dnsize(objset_t *os, uint64_t object, dmu_object_type_t ot, err = dnode_hold_impl(os, object, DNODE_MUST_BE_FREE, dn_slots, FTAG, &dn); - if (err) + if (err) { + dprintf("%s:%d: returning error %d\n", __func__, __LINE__, + err); return (err); + } dnode_allocate(dn, ot, blocksize, 0, bonustype, bonuslen, dn_slots, tx); dmu_tx_add_new_object(tx, dn); dnode_rele(dn, FTAG); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } diff --git a/module/zfs/dmu_objset.c b/module/zfs/dmu_objset.c index af107fb8ad63..4e13bb3039ac 100644 --- a/module/zfs/dmu_objset.c +++ b/module/zfs/dmu_objset.c @@ -694,11 +694,14 @@ dmu_objset_hold_flags(const char *name, boolean_t decrypt, void *tag, flags = (decrypt) ? DS_HOLD_FLAG_DECRYPT : DS_HOLD_FLAG_NONE; err = dsl_pool_hold(name, tag, &dp); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } err = dsl_dataset_hold_flags(dp, name, flags, tag, &ds); if (err != 0) { dsl_pool_rele(dp, tag); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -708,6 +711,8 @@ dmu_objset_hold_flags(const char *name, boolean_t decrypt, void *tag, dsl_pool_rele(dp, tag); } + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -2829,11 +2834,14 @@ dmu_objset_find_impl(spa_t *spa, const char *name, uint64_t thisobj; int err; + dprintf("%s:%d: name = %s, flags = %d\n", __func__, __LINE__, + (name ? name : "NULL"), flags); dsl_pool_config_enter(dp, FTAG); err = dsl_dir_hold(dp, name, FTAG, &dd, NULL); if (err != 0) { dsl_pool_config_exit(dp, FTAG); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -2841,6 +2849,8 @@ dmu_objset_find_impl(spa_t *spa, const char *name, if (dd->dd_myname[0] == '$') { dsl_dir_rele(dd, FTAG); dsl_pool_config_exit(dp, FTAG); + dprintf("%s:%d: dd->dd_myname = %s. Returning 0\n", __func__, + __LINE__, dd->dd_myname); return (0); } @@ -2874,6 +2884,8 @@ dmu_objset_find_impl(spa_t *spa, const char *name, dsl_dir_rele(dd, FTAG); dsl_pool_config_exit(dp, FTAG); kmem_free(attr, sizeof (zap_attribute_t)); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); } } @@ -2914,9 +2926,10 @@ dmu_objset_find_impl(spa_t *spa, const char *name, kmem_free(attr, sizeof (zap_attribute_t)); dsl_pool_config_exit(dp, FTAG); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); - + } /* Apply to self. */ return (func(name, arg)); } @@ -2932,8 +2945,10 @@ dmu_objset_find(const char *name, int func(const char *, void *), void *arg, int error; error = spa_open(name, &spa, FTAG); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); + } error = dmu_objset_find_impl(spa, name, func, arg, flags); spa_close(spa, FTAG); return (error); diff --git a/module/zfs/dnode.c b/module/zfs/dnode.c index 3ed9c4b68ab1..31293466d93b 100644 --- a/module/zfs/dnode.c +++ b/module/zfs/dnode.c @@ -591,8 +591,8 @@ dnode_allocate(dnode_t *dn, dmu_object_type_t ot, int blocksize, int ibs, ibs = MIN(MAX(ibs, DN_MIN_INDBLKSHIFT), DN_MAX_INDBLKSHIFT); - dprintf("os=%p obj=%llu txg=%llu blocksize=%d ibs=%d dn_slots=%d\n", - dn->dn_objset, (u_longlong_t)dn->dn_object, + TraceEvent(5, "os=%p obj=%llu txg=%llu blocksize=%d ibs=%d dn_slots=" + "%d\n", dn->dn_objset, (u_longlong_t)dn->dn_object, (u_longlong_t)tx->tx_txg, blocksize, ibs, dn_slots); DNODE_STAT_BUMP(dnode_allocate); @@ -1110,15 +1110,25 @@ dnode_check_slots_free(dnode_children_t *children, int idx, int slots) !DNODE_IS_DIRTY(dn)); mutex_exit(&dn->dn_mtx); - if (!can_free) + if (!can_free) { + dprintf("%s:%d: dn->dn_type = %d, " + "zfs_refcount_is_zero(&dn->dn_holds) = %d." + " Returning B_FALSE = %d\n", + __func__, __LINE__, dn->dn_type, + zfs_refcount_is_zero(&dn->dn_holds), + B_FALSE); return (B_FALSE); - else + } else continue; } else { + dprintf("%s:%d: Returning B_FALSE = %d\n", __func__, + __LINE__, B_FALSE); return (B_FALSE); } } + TraceEvent(8, "%s:%d: Returning B_TRUE = %d\n", __func__, __LINE__, + B_TRUE); return (B_TRUE); } @@ -1284,6 +1294,10 @@ dnode_hold_impl(objset_t *os, uint64_t object, int flag, int slots, dnode_phys_t *dn_block; dnode_handle_t *dnh; + TraceEvent(8, "%s:%d: os = 0x%p, object = %llu, flag = %d, slots = %d," + " tag = 0x%p, dnp = 0x%p", __func__, __LINE__, os, object, flag, + slots, tag, dnp); + ASSERT(!(flag & DNODE_MUST_BE_ALLOCATED) || (slots == 0)); ASSERT(!(flag & DNODE_MUST_BE_FREE) || (slots > 0)); IMPLY(flag & DNODE_DRY_RUN, (tag == NULL) && (dnp == NULL)); @@ -1310,17 +1324,21 @@ dnode_hold_impl(objset_t *os, uint64_t object, int flag, int slots, dn = DMU_PROJECTUSED_DNODE(os); if (dn == NULL) return (SET_ERROR(ENOENT)); + type = dn->dn_type; if ((flag & DNODE_MUST_BE_ALLOCATED) && type == DMU_OT_NONE) return (SET_ERROR(ENOENT)); + if ((flag & DNODE_MUST_BE_FREE) && type != DMU_OT_NONE) return (SET_ERROR(EEXIST)); + DNODE_VERIFY(dn); /* Don't actually hold if dry run, just return 0 */ if (!(flag & DNODE_DRY_RUN)) { (void) zfs_refcount_add(&dn->dn_holds, tag); *dnp = dn; } + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1355,6 +1373,7 @@ dnode_hold_impl(objset_t *os, uint64_t object, int flag, int slots, if (err) { DNODE_STAT_BUMP(dnode_hold_dbuf_read); dbuf_rele(db, FTAG); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -1559,6 +1578,7 @@ dnode_hold_impl(objset_t *os, uint64_t object, int flag, int slots, dbuf_rele(db, FTAG); *dnp = dn; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } diff --git a/module/zfs/dnode_sync.c b/module/zfs/dnode_sync.c index dd37e3af7ed5..56e0b06dd7b2 100644 --- a/module/zfs/dnode_sync.c +++ b/module/zfs/dnode_sync.c @@ -136,8 +136,8 @@ free_blocks(dnode_t *dn, blkptr_t *bp, int num, dmu_tx_t *tx) dsl_dataset_t *ds = dn->dn_objset->os_dsl_dataset; uint64_t bytesfreed = 0; - dprintf("ds=%p obj=%llx num=%d\n", ds, (u_longlong_t)dn->dn_object, - num); + TraceEvent(5, "ds=%p obj=%llx num=%d\n", ds, + (u_longlong_t)dn->dn_object, num); for (int i = 0; i < num; i++, bp++) { if (BP_IS_HOLE(bp)) diff --git a/module/zfs/dsl_crypt.c b/module/zfs/dsl_crypt.c index 26d4c2fe7e33..433e9adf6f00 100644 --- a/module/zfs/dsl_crypt.c +++ b/module/zfs/dsl_crypt.c @@ -384,6 +384,7 @@ spa_keystore_wkey_hold_ddobj_impl(spa_t *spa, uint64_t ddobj, found_wkey = avl_find(&spa->spa_keystore.sk_wkeys, &search_wkey, NULL); if (!found_wkey) { ret = SET_ERROR(ENOENT); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, ret); goto error; } @@ -391,6 +392,7 @@ spa_keystore_wkey_hold_ddobj_impl(spa_t *spa, uint64_t ddobj, dsl_wrapping_key_hold(found_wkey, tag); *wkey_out = found_wkey; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); error: @@ -427,6 +429,7 @@ spa_keystore_wkey_hold_dd(spa_t *spa, dsl_dir_t *dd, void *tag, rw_exit(&spa->spa_keystore.sk_wkeys_lock); *wkey_out = wkey; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); error: @@ -434,6 +437,11 @@ spa_keystore_wkey_hold_dd(spa_t *spa, dsl_dir_t *dd, void *tag, rw_exit(&spa->spa_keystore.sk_wkeys_lock); *wkey_out = NULL; + if (ret) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, ret); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, + __LINE__, ret); return (ret); } @@ -624,6 +632,7 @@ spa_keystore_dsl_key_hold_impl(spa_t *spa, uint64_t dckobj, void *tag, zfs_refcount_add(&found_dck->dck_holds, tag); *dck_out = found_dck; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); error: @@ -1135,6 +1144,7 @@ dmu_objset_check_wkey_loaded(dsl_dir_t *dd) dsl_wrapping_key_rele(wkey, FTAG); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1154,6 +1164,7 @@ dsl_dir_get_crypt(dsl_dir_t *dd, uint64_t *crypt) { if (dd->dd_crypto_obj == 0) { *crypt = ZIO_CRYPT_OFF; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1760,8 +1771,13 @@ dmu_objset_create_crypt_check(dsl_dir_t *parentdd, dsl_crypto_params_t *dcp, uint64_t pcrypt, crypt; dsl_crypto_params_t dummy_dcp = { 0 }; - if (will_encrypt != NULL) + dprintf("%s:%d: parentdd = 0x%p, dcp = 0x%p\n", __func__, + __LINE__, parentdd, dcp); + if (will_encrypt != NULL) { + dprintf("%s:%d: will_encrypt = %d\n", __func__, + __LINE__, will_encrypt); *will_encrypt = B_FALSE; + } if (dcp == NULL) dcp = &dummy_dcp; @@ -1771,8 +1787,11 @@ dmu_objset_create_crypt_check(dsl_dir_t *parentdd, dsl_crypto_params_t *dcp, if (parentdd != NULL) { ret = dsl_dir_get_crypt(parentdd, &pcrypt); - if (ret != 0) + if (ret != 0) { + dprintf("%s:%d: Returning %d\n", __func__, + __LINE__, ret); return (ret); + } } else { pcrypt = ZIO_CRYPT_OFF; } @@ -1790,6 +1809,7 @@ dmu_objset_create_crypt_check(dsl_dir_t *parentdd, dsl_crypto_params_t *dcp, strcmp(dcp->cp_keylocation, "none") != 0)) return (SET_ERROR(EINVAL)); + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1803,16 +1823,14 @@ dmu_objset_create_crypt_check(dsl_dir_t *parentdd, dsl_crypto_params_t *dcp, */ if (parentdd != NULL && !spa_feature_is_enabled(parentdd->dd_pool->dp_spa, - SPA_FEATURE_ENCRYPTION)) { + SPA_FEATURE_ENCRYPTION)) return (SET_ERROR(EOPNOTSUPP)); - } /* Check for errata #4 (encryption enabled, bookmark_v2 disabled) */ if (parentdd != NULL && !spa_feature_is_enabled(parentdd->dd_pool->dp_spa, - SPA_FEATURE_BOOKMARK_V2)) { + SPA_FEATURE_BOOKMARK_V2)) return (SET_ERROR(EOPNOTSUPP)); - } /* handle inheritance */ if (dcp->cp_wkey == NULL) { @@ -1831,6 +1849,7 @@ dmu_objset_create_crypt_check(dsl_dir_t *parentdd, dsl_crypto_params_t *dcp, if (ret != 0) return (ret); + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1859,6 +1878,7 @@ dmu_objset_create_crypt_check(dsl_dir_t *parentdd, dsl_crypto_params_t *dcp, return (SET_ERROR(EINVAL)); } + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); } diff --git a/module/zfs/dsl_dataset.c b/module/zfs/dsl_dataset.c index 1c03216ef6d5..7ea275e0b27b 100644 --- a/module/zfs/dsl_dataset.c +++ b/module/zfs/dsl_dataset.c @@ -477,15 +477,22 @@ dsl_dataset_get_snapname(dsl_dataset_t *ds) dsl_pool_t *dp = ds->ds_dir->dd_pool; objset_t *mos = dp->dp_meta_objset; - if (ds->ds_snapname[0]) + if (ds->ds_snapname[0]) { + dprintf("%s:%d: ds->ds_snapname = %s. Returning 0\n", __func__, + __LINE__, ds->ds_snapname); return (0); - if (dsl_dataset_phys(ds)->ds_next_snap_obj == 0) + } + if (dsl_dataset_phys(ds)->ds_next_snap_obj == 0) { + TraceEvent(5, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } err = dmu_bonus_hold(mos, dsl_dir_phys(ds->ds_dir)->dd_head_dataset_obj, FTAG, &headdbuf); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } headphys = headdbuf->db_data; err = zap_value_search(dp->dp_meta_objset, headphys->ds_snapnames_zapobj, ds->ds_object, 0, ds->ds_snapname); @@ -496,6 +503,7 @@ dsl_dataset_get_snapname(dsl_dataset_t *ds) (unsigned long long)ds->ds_object, err); } dmu_buf_rele(headdbuf, FTAG); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -573,8 +581,10 @@ dsl_dataset_hold_obj(dsl_pool_t *dp, uint64_t dsobj, void *tag, ASSERT(dsl_pool_config_held(dp)); err = dmu_bonus_hold(mos, dsobj, tag, &dbuf); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } /* Make sure dsobj has the correct object type. */ dmu_object_info_from_db(dbuf, &doi); @@ -598,6 +608,8 @@ dsl_dataset_hold_obj(dsl_pool_t *dp, uint64_t dsobj, void *tag, if (err != 0) { kmem_free(ds, sizeof (dsl_dataset_t)); dmu_buf_rele(dbuf, tag); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); } @@ -707,6 +719,8 @@ dsl_dataset_hold_obj(dsl_pool_t *dp, uint64_t dsobj, void *tag, kmem_free(ds, sizeof (dsl_dataset_t)); if (err != 0) { dmu_buf_rele(dbuf, tag); + dprintf("%s:%d: Returning %d\n", __func__, + __LINE__, err); return (err); } ds = winner; @@ -733,6 +747,7 @@ dsl_dataset_hold_obj(dsl_pool_t *dp, uint64_t dsobj, void *tag, dp->dp_origin_snap == NULL || ds == dp->dp_origin_snap); *dsp = ds; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -741,8 +756,10 @@ dsl_dataset_create_key_mapping(dsl_dataset_t *ds) { dsl_dir_t *dd = ds->ds_dir; - if (dd->dd_crypto_obj == 0) + if (dd->dd_crypto_obj == 0) { + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } return (spa_keystore_create_mapping(dd->dd_pool->dp_spa, ds, ds, &ds->ds_key_mapping)); @@ -780,15 +797,19 @@ dsl_dataset_hold_flags(dsl_pool_t *dp, const char *name, ds_hold_flags_t flags, dsl_dataset_t *ds; err = dsl_dir_hold(dp, name, FTAG, &dd, &snapname); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); - + } ASSERT(dsl_pool_config_held(dp)); obj = dsl_dir_phys(dd)->dd_head_dataset_obj; - if (obj != 0) + if (obj != 0) { err = dsl_dataset_hold_obj_flags(dp, obj, flags, tag, &ds); - else + if (err) + dprintf("%s:%d: err = %d\n", __func__, __LINE__, err); + } else { err = SET_ERROR(ENOENT); + } /* we may be looking for a snapshot */ if (err == 0 && snapname != NULL) { @@ -800,7 +821,8 @@ dsl_dataset_hold_flags(dsl_pool_t *dp, const char *name, ds_hold_flags_t flags, return (SET_ERROR(ENOENT)); } - dprintf("looking for snapshot '%s'\n", snapname); + dprintf("%s:%d: looking for snapshot '%s'\n", __func__, + __LINE__, snapname); err = dsl_dataset_snap_lookup(ds, snapname, &obj); if (err == 0) { err = dsl_dataset_hold_obj_flags(dp, obj, flags, tag, @@ -820,6 +842,9 @@ dsl_dataset_hold_flags(dsl_pool_t *dp, const char *name, ds_hold_flags_t flags, if (err == 0) *dsp = ds; dsl_dir_rele(dd, FTAG); + + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } diff --git a/module/zfs/dsl_dir.c b/module/zfs/dsl_dir.c index df2c3d8f0637..036573a07c2e 100644 --- a/module/zfs/dsl_dir.c +++ b/module/zfs/dsl_dir.c @@ -172,8 +172,10 @@ dsl_dir_hold_obj(dsl_pool_t *dp, uint64_t ddobj, ASSERT(dsl_pool_config_held(dp)); err = dmu_bonus_hold(dp->dp_meta_objset, ddobj, tag, &dbuf); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } dd = dmu_buf_get_user(dbuf); dmu_object_info_from_db(dbuf, &doi); @@ -215,8 +217,11 @@ dsl_dir_hold_obj(dsl_pool_t *dp, uint64_t ddobj, err = dsl_dir_hold_obj(dp, dsl_dir_phys(dd)->dd_parent_obj, NULL, dd, &dd->dd_parent); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Jumping to errout\n", + __func__, __LINE__); goto errout; + } if (tail) { #ifdef ZFS_DEBUG uint64_t foundobj; @@ -235,8 +240,11 @@ dsl_dir_hold_obj(dsl_pool_t *dp, uint64_t ddobj, dd_child_dir_zapobj, ddobj, 0, dd->dd_myname); } - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Jumping to errout\n", + __func__, __LINE__); goto errout; + } } else { (void) strlcpy(dd->dd_myname, spa_name(dp->dp_spa), sizeof (dd->dd_myname)); @@ -254,8 +262,11 @@ dsl_dir_hold_obj(dsl_pool_t *dp, uint64_t ddobj, err = dmu_bonus_hold(dp->dp_meta_objset, dsl_dir_phys(dd)->dd_origin_obj, FTAG, &origin_bonus); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Jumping to errout\n", __func__, + __LINE__); goto errout; + } origin_phys = origin_bonus->db_data; dd->dd_origin_txg = origin_phys->ds_creation_txg; @@ -305,6 +316,7 @@ dsl_dir_hold_obj(dsl_pool_t *dp, uint64_t ddobj, ASSERT3U(dd->dd_object, ==, ddobj); ASSERT3P(dd->dd_dbuf, ==, dbuf); *ddp = dd; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); errout: @@ -318,6 +330,7 @@ dsl_dir_hold_obj(dsl_pool_t *dp, uint64_t ddobj, mutex_destroy(&dd->dd_lock); kmem_free(dd, sizeof (dsl_dir_t)); dmu_buf_rele(dbuf, tag); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -398,8 +411,11 @@ getcomponent(const char *path, char *component, const char **nextp) { char *p; + TraceEvent(8, "%s:%d: path = %s\n", __func__, __LINE__, + (path ? path : "NULL")); if ((path == NULL) || (path[0] == '\0')) return (SET_ERROR(ENOENT)); + /* This would be a good place to reserve some namespace... */ p = strpbrk(path, "/@"); if (p && (p[1] == '/' || p[1] == '@')) { @@ -413,15 +429,18 @@ getcomponent(const char *path, char *component, const char **nextp) * and it had better have something after the @. */ if (p != NULL && - (p[0] != '@' || strpbrk(path+1, "/@") || p[1] == '\0')) + (p[0] != '@' || strpbrk(path + 1, "/@") || p[1] == '\0')) return (SET_ERROR(EINVAL)); + if (strlen(path) >= ZFS_MAX_DATASET_NAME_LEN) return (SET_ERROR(ENAMETOOLONG)); + (void) strlcpy(component, path, ZFS_MAX_DATASET_NAME_LEN); p = NULL; } else if (p[0] == '/') { if (p - path >= ZFS_MAX_DATASET_NAME_LEN) return (SET_ERROR(ENAMETOOLONG)); + (void) strncpy(component, path, p - path); component[p - path] = '\0'; p++; @@ -432,14 +451,17 @@ getcomponent(const char *path, char *component, const char **nextp) */ if (strchr(path, '/')) return (SET_ERROR(EINVAL)); + if (p - path >= ZFS_MAX_DATASET_NAME_LEN) return (SET_ERROR(ENAMETOOLONG)); + (void) strncpy(component, path, p - path); component[p - path] = '\0'; } else { panic("invalid p=%p", (void *)p); } *nextp = p; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -476,6 +498,7 @@ dsl_dir_hold(dsl_pool_t *dp, const char *name, void *tag, err = dsl_dir_hold_obj(dp, dp->dp_root_dir_obj, NULL, tag, &dd); if (err != 0) { + dprintf("%s:%d: Jumping to error\n", __func__, __LINE__); goto error; } @@ -487,7 +510,7 @@ dsl_dir_hold(dsl_pool_t *dp, const char *name, void *tag, ASSERT(next[0] != '\0'); if (next[0] == '@') break; - dprintf("looking up %s in obj%lld\n", + TraceEvent(5, "looking up %s in obj%lld\n", buf, (longlong_t)dsl_dir_phys(dd)->dd_child_dir_zapobj); err = zap_lookup(dp->dp_meta_objset, @@ -520,7 +543,6 @@ dsl_dir_hold(dsl_pool_t *dp, const char *name, void *tag, (tailp == NULL || (nextnext && nextnext[0] != '\0'))) { /* bad path name */ dsl_dir_rele(dd, tag); - dprintf("next=%p (%s) tail=%p\n", next, next?next:"", tailp); err = SET_ERROR(ENOENT); } if (tailp != NULL) @@ -529,6 +551,7 @@ dsl_dir_hold(dsl_pool_t *dp, const char *name, void *tag, *ddp = dd; error: kmem_free(buf, ZFS_MAX_DATASET_NAME_LEN); + TraceEvent(5, "%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -1349,6 +1372,7 @@ dsl_dir_tempreserve_impl(dsl_dir_t *dd, uint64_t asize, boolean_t netfree, (u_longlong_t)quota>>10, (u_longlong_t)asize>>10, retval); mutex_exit(&dd->dd_lock); DMU_TX_STAT_BUMP(dmu_tx_quota); + return (SET_ERROR(retval)); } diff --git a/module/zfs/dsl_pool.c b/module/zfs/dsl_pool.c index e66c136a9e02..8592013f8886 100644 --- a/module/zfs/dsl_pool.c +++ b/module/zfs/dsl_pool.c @@ -1320,6 +1320,8 @@ dsl_pool_hold(const char *name, void *tag, dsl_pool_t **dp) *dp = spa_get_dsl(spa); dsl_pool_config_enter(*dp, tag); } + if (error) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } diff --git a/module/zfs/dsl_prop.c b/module/zfs/dsl_prop.c index f6ff9ae47192..ed42ac5aef3c 100644 --- a/module/zfs/dsl_prop.c +++ b/module/zfs/dsl_prop.c @@ -57,6 +57,7 @@ dodefault(zfs_prop_t prop, int intsz, int numints, void *buf) if (zfs_prop_get_type(prop) == PROP_TYPE_STRING) { if (intsz != 1) return (SET_ERROR(EOVERFLOW)); + (void) strncpy(buf, zfs_prop_default_string(prop), numints); } else { @@ -66,6 +67,7 @@ dodefault(zfs_prop_t prop, int intsz, int numints, void *buf) *(uint64_t *)buf = zfs_prop_default_numeric(prop); } + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -182,6 +184,8 @@ dsl_prop_get_ds(dsl_dataset_t *ds, const char *propname, if (err != ENOENT) { if (setpoint != NULL && err == 0) dsl_dataset_name(ds, setpoint); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); } @@ -194,8 +198,11 @@ dsl_prop_get_ds(dsl_dataset_t *ds, const char *propname, ZPROP_INHERIT_SUFFIX); err = zap_contains(mos, zapobj, inheritstr); kmem_strfree(inheritstr); - if (err != 0 && err != ENOENT) + if (err != 0 && err != ENOENT) { + dprintf("%s:%d: Returning %d\n", __func__, + __LINE__, err); return (err); + } } if (err == ENOENT) { @@ -210,6 +217,8 @@ dsl_prop_get_ds(dsl_dataset_t *ds, const char *propname, (void) strlcpy(setpoint, ZPROP_SOURCE_VAL_RECVD, MAXNAMELEN); + dprintf("%s:%d: Returning %d\n", __func__, + __LINE__, err); return (err); } } @@ -896,6 +905,7 @@ dsl_props_set_check(void *arg, dmu_tx_t *tx) return (SET_ERROR(ENOTSUP)); } dsl_dataset_rele(ds, FTAG); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } diff --git a/module/zfs/dsl_synctask.c b/module/zfs/dsl_synctask.c index 148e8fff2437..986315fc4a9f 100644 --- a/module/zfs/dsl_synctask.c +++ b/module/zfs/dsl_synctask.c @@ -51,8 +51,10 @@ dsl_sync_task_common(const char *pool, dsl_checkfunc_t *checkfunc, dsl_pool_t *dp; err = spa_open(pool, &spa, FTAG); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } dp = spa_get_dsl(spa); top: @@ -76,6 +78,7 @@ dsl_sync_task_common(const char *pool, dsl_checkfunc_t *checkfunc, if (err != 0) { dmu_tx_commit(tx); spa_close(spa, FTAG); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -98,6 +101,9 @@ dsl_sync_task_common(const char *pool, dsl_checkfunc_t *checkfunc, } spa_close(spa, FTAG); + if (dst.dst_error) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + dst.dst_error); return (dst.dst_error); } diff --git a/module/zfs/spa.c b/module/zfs/spa.c index 9ae2b65c5f08..836d1d1ef590 100644 --- a/module/zfs/spa.c +++ b/module/zfs/spa.c @@ -534,6 +534,8 @@ spa_prop_validate(spa_t *spa, nvlist_t *props) uint64_t objnum = 0; boolean_t has_feature = B_FALSE; + dprintf("%s:%d: spa = 0x%p, props = 0x%p\n", __func__, __LINE__, spa, + props); elem = NULL; while ((elem = nvlist_next_nvpair(props, elem)) != NULL) { uint64_t intval; @@ -577,10 +579,9 @@ spa_prop_validate(spa_t *spa, nvlist_t *props) case ZPOOL_PROP_VERSION: error = nvpair_value_uint64(elem, &intval); - if (!error && - (intval < spa_version(spa) || + if (!error && (intval < spa_version(spa) || intval > SPA_VERSION_BEFORE_FEATURES || - has_feature)) + has_feature)) error = SET_ERROR(EINVAL); break; @@ -631,6 +632,8 @@ spa_prop_validate(spa_t *spa, nvlist_t *props) reset_bootfs = 1; error = nvpair_value_string(elem, &strval); + dprintf("%s:%d: error = %d\n", __func__, __LINE__, + error); if (!error) { objset_t *os; @@ -642,8 +645,11 @@ spa_prop_validate(spa_t *spa, nvlist_t *props) } error = dmu_objset_hold(strval, FTAG, &os); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Setting error = %d\n", + __func__, __LINE__, error); break; + } /* Must be ZPL. */ if (dmu_objset_type(os) != DMU_OST_ZFS) { @@ -727,12 +733,16 @@ spa_prop_validate(spa_t *spa, nvlist_t *props) error = nvlist_remove(props, zpool_prop_to_name(ZPOOL_PROP_BOOTFS), DATA_TYPE_STRING); + dprintf("%s:%d: nvlist_remove returned with %d\n", __func__, + __LINE__, error); + if (!error) { error = nvlist_add_uint64(props, zpool_prop_to_name(ZPOOL_PROP_BOOTFS), objnum); } } + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -768,8 +778,10 @@ spa_prop_set(spa_t *spa, nvlist_t *nvp) nvpair_t *elem = NULL; boolean_t need_sync = B_FALSE; - if ((error = spa_prop_validate(spa, nvp)) != 0) + if ((error = spa_prop_validate(spa, nvp)) != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); + } while ((elem = nvlist_next_nvpair(nvp, elem)) != NULL) { zpool_prop_t prop = zpool_name_to_prop(nvpair_name(elem)); @@ -817,6 +829,7 @@ spa_prop_set(spa_t *spa, nvlist_t *nvp) nvp, 6, ZFS_SPACE_CHECK_RESERVED)); } + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1468,17 +1481,23 @@ spa_config_parse(spa_t *spa, vdev_t **vdp, nvlist_t *nv, vdev_t *parent, uint_t children; int error; - if ((error = vdev_alloc(spa, vdp, nv, parent, id, atype)) != 0) + if ((error = vdev_alloc(spa, vdp, nv, parent, id, atype)) != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); + } - if ((*vdp)->vdev_ops->vdev_op_leaf) + if ((*vdp)->vdev_ops->vdev_op_leaf) { + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } error = nvlist_lookup_nvlist_array(nv, ZPOOL_CONFIG_CHILDREN, &child, &children); - if (error == ENOENT) + if (error == ENOENT) { + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } if (error) { vdev_free(*vdp); @@ -1492,12 +1511,15 @@ spa_config_parse(spa_t *spa, vdev_t **vdp, nvlist_t *nv, vdev_t *parent, atype)) != 0) { vdev_free(*vdp); *vdp = NULL; + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + error); return (error); } } ASSERT(*vdp != NULL); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -5014,6 +5036,10 @@ spa_load_best(spa_t *spa, spa_load_state_t state, uint64_t max_request, uint64_t safe_rewind_txg; uint64_t min_txg; + dprintf("%s:%d: spa = 0x%p, state = %d, max_request = %llu, " + "rewind_flags = %d\n", __func__, __LINE__, spa, state, + max_request, rewind_flags); + if (spa->spa_load_txg && state == SPA_LOAD_RECOVER) { spa->spa_load_max_txg = spa->spa_load_txg; spa_set_log_state(spa, SPA_LOG_CLEAR); @@ -5024,8 +5050,10 @@ spa_load_best(spa_t *spa, spa_load_state_t state, uint64_t max_request, } load_error = rewind_error = spa_load(spa, state, SPA_IMPORT_EXISTING); - if (load_error == 0) + if (load_error == 0) { + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } if (load_error == ZFS_ERR_NO_CHECKPOINT) { /* * When attempting checkpoint-rewind on a pool with no @@ -5034,6 +5062,8 @@ spa_load_best(spa_t *spa, spa_load_state_t state, uint64_t max_request, */ ASSERT(spa->spa_import_flags & ZFS_IMPORT_CHECKPOINT); spa_import_progress_remove(spa_guid(spa)); + dprintf("%s:%d: Returning (ZFS_ERR_NO_CHECKPOINT) %d\n", + __func__, __LINE__, load_error); return (load_error); } @@ -5046,6 +5076,8 @@ spa_load_best(spa_t *spa, spa_load_state_t state, uint64_t max_request, if (rewind_flags & ZPOOL_NEVER_REWIND) { nvlist_free(config); spa_import_progress_remove(spa_guid(spa)); + dprintf("%s:%d: rewind_flags = %d. Returning %d\n", __func__, + __LINE__, rewind_flags, load_error); return (load_error); } @@ -5089,6 +5121,8 @@ spa_load_best(spa_t *spa, spa_load_state_t state, uint64_t max_request, if (state == SPA_LOAD_RECOVER) { ASSERT3P(loadinfo, ==, NULL); spa_import_progress_remove(spa_guid(spa)); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + rewind_error); return (rewind_error); } else { /* Store the rewind info as part of the initial load info */ @@ -5100,6 +5134,8 @@ spa_load_best(spa_t *spa, spa_load_state_t state, uint64_t max_request, spa->spa_load_info = loadinfo; spa_import_progress_remove(spa_guid(spa)); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + load_error); return (load_error); } } @@ -5128,6 +5164,9 @@ spa_open_common(const char *pool, spa_t **spapp, void *tag, nvlist_t *nvpolicy, *spapp = NULL; + TraceEvent(8, "%s:%d: pool = %s\n", __func__, __LINE__, + (pool ? pool : "NULL")); + /* * As disgusting as this is, we need to support recursive calls to this * function because dsl_dir_open() is called during spa_load(), and ends @@ -5201,6 +5240,8 @@ spa_open_common(const char *pool, spa_t **spapp, void *tag, nvlist_t *nvpolicy, if (locked) mutex_exit(&spa_namespace_lock); *spapp = NULL; + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + error); return (error); } } @@ -5231,6 +5272,7 @@ spa_open_common(const char *pool, spa_t **spapp, void *tag, nvlist_t *nvpolicy, *spapp = spa; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -5555,11 +5597,17 @@ spa_validate_aux_devs(spa_t *spa, nvlist_t *nvroot, uint64_t crtxg, int mode, ASSERT(spa_config_held(spa, SCL_ALL, RW_WRITER) == SCL_ALL); + dprintf("%s:%d: spa = 0x%p, nvroot = 0x%p, crtxg = %llu, mode = %d, " + "sav = 0x%p, config = 0x%p, version = %llu, label = %d\n", + __func__, __LINE__, spa, nvroot, crtxg, mode, sav, config, version, + label); /* * It's acceptable to have no devs specified. */ - if (nvlist_lookup_nvlist_array(nvroot, config, &dev, &ndev) != 0) + if (nvlist_lookup_nvlist_array(nvroot, config, &dev, &ndev) != 0) { + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } if (ndev == 0) return (SET_ERROR(EINVAL)); @@ -5580,8 +5628,11 @@ spa_validate_aux_devs(spa_t *spa, nvlist_t *nvroot, uint64_t crtxg, int mode, for (i = 0; i < ndev; i++) { if ((error = spa_config_parse(spa, &vd, dev[i], NULL, 0, - mode)) != 0) + mode)) != 0) { + dprintf("%s:%d: error = %d. Jumping to out label\n", + __func__, __LINE__, error); goto out; + } if (!vd->vdev_ops->vdev_op_leaf) { vdev_free(vd); @@ -5600,15 +5651,21 @@ spa_validate_aux_devs(spa_t *spa, nvlist_t *nvroot, uint64_t crtxg, int mode, vdev_free(vd); if (error && - (mode != VDEV_ALLOC_SPARE && mode != VDEV_ALLOC_L2CACHE)) + (mode != VDEV_ALLOC_SPARE && mode != VDEV_ALLOC_L2CACHE)) { + dprintf("%s:%d: error = %d. mode = %d. Jumping to out " + "label\n", __func__, __LINE__, error, mode); goto out; - else + } else { error = 0; + dprintf("%s:%d: Setting error = %d\n", __func__, + __LINE__, error); + } } out: sav->sav_pending = NULL; sav->sav_npending = 0; + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -5622,6 +5679,7 @@ spa_validate_aux(spa_t *spa, nvlist_t *nvroot, uint64_t crtxg, int mode) if ((error = spa_validate_aux_devs(spa, nvroot, crtxg, mode, &spa->spa_spares, ZPOOL_CONFIG_SPARES, SPA_VERSION_SPARES, VDEV_LABEL_SPARE)) != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -5739,6 +5797,10 @@ spa_create(const char *pool, nvlist_t *nvroot, nvlist_t *props, char *poolname; nvlist_t *nvl; + dprintf("%s:%d: pool = 0x%p, nvroot = 0x%p, props = 0x%p, zplprops = " + "0x%p, dcp = 0x%p\n", __func__, __LINE__, pool, nvroot, props, + zplprops, dcp); + if (props == NULL || nvlist_lookup_string(props, "tname", &poolname) != 0) poolname = (char *)pool; @@ -5767,6 +5829,8 @@ spa_create(const char *pool, nvlist_t *nvroot, nvlist_t *props, spa_deactivate(spa); spa_remove(spa); mutex_exit(&spa_namespace_lock); + dprintf("%s:%d: props = 0x%p. Returning %d\n", __func__, + __LINE__, props, error); return (error); } @@ -5800,6 +5864,8 @@ spa_create(const char *pool, nvlist_t *nvroot, nvlist_t *props, spa_deactivate(spa); spa_remove(spa); mutex_exit(&spa_namespace_lock); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + error); return (error); } } @@ -5807,6 +5873,8 @@ spa_create(const char *pool, nvlist_t *nvroot, nvlist_t *props, spa_deactivate(spa); spa_remove(spa); mutex_exit(&spa_namespace_lock); + dprintf("%s:%d: Returning (ENOTSUP) %d\n", __func__, __LINE__, + ENOTSUP); return (ENOTSUP); } @@ -6017,7 +6085,7 @@ spa_create(const char *pool, nvlist_t *nvroot, nvlist_t *props, spa->spa_load_state = SPA_LOAD_NONE; mutex_exit(&spa_namespace_lock); - + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -6038,6 +6106,8 @@ spa_import(char *pool, nvlist_t *config, nvlist_t *props, uint64_t flags) nvlist_t **spares, **l2cache; uint_t nspares, nl2cache; + dprintf("%s:%d: pool = %s, config = 0x%p, props = 0x%p, " + "flags = %llu\n", __func__, __LINE__, pool, config, props, flags); /* * If a pool with this name exists, return failure. */ @@ -6071,6 +6141,7 @@ spa_import(char *pool, nvlist_t *config, nvlist_t *props, uint64_t flags) spa_event_notify(spa, NULL, NULL, ESC_ZFS_POOL_IMPORT); zfs_dbgmsg("spa_import: verbatim import of %s", pool); mutex_exit(&spa_namespace_lock); + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -6132,6 +6203,8 @@ spa_import(char *pool, nvlist_t *config, nvlist_t *props, uint64_t flags) spa_deactivate(spa); spa_remove(spa); mutex_exit(&spa_namespace_lock); + dprintf("%s:%d: Returing %d\n", + __func__, __LINE__, error); return (error); } @@ -6201,6 +6274,7 @@ spa_import(char *pool, nvlist_t *config, nvlist_t *props, uint64_t flags) zvol_create_minors_recursive(pool); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -6333,6 +6407,10 @@ spa_export_common(const char *pool, int new_state, nvlist_t **oldconfig, int error; spa_t *spa; + dprintf("%s:%d: pool = %s, new_state = %d, force = %d, hardforce = " + "%d\n", __func__, __LINE__, (pool ? pool : "NULL"), + new_state, force, hardforce); + if (oldconfig) *oldconfig = NULL; @@ -6459,6 +6537,7 @@ spa_export_common(const char *pool, int new_state, nvlist_t **oldconfig, } mutex_exit(&spa_namespace_lock); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); fail: @@ -6550,11 +6629,17 @@ spa_vdev_add(spa_t *spa, nvlist_t *nvroot) &nl2cache) != 0) nl2cache = 0; - if (vd->vdev_children == 0 && nspares == 0 && nl2cache == 0) + if (vd->vdev_children == 0 && nspares == 0 && nl2cache == 0) { + dprintf("%s:%d: vd->vdev_children = %llu, spares = 0x%p, " + "nl2cache = = %u", __func__, __LINE__, vd->vdev_children, + spares, nl2cache); return (spa_vdev_exit(spa, vd, txg, EINVAL)); + } if (vd->vdev_children != 0 && (error = vdev_create(vd, txg, B_FALSE)) != 0) { + dprintf("%s:%d: vd->vdev_children = %llu, error = = %d", + __func__, __LINE__, vd->vdev_children, error); return (spa_vdev_exit(spa, vd, txg, error)); } @@ -6569,6 +6654,7 @@ spa_vdev_add(spa_t *spa, nvlist_t *nvroot) ZPOOL_CONFIG_SPARES, &spares, &nspares) != 0) nspares = 0; } else { + dprintf("%s:%d: error = = %d", __func__, __LINE__, error); return (spa_vdev_exit(spa, vd, txg, error)); } @@ -6591,11 +6677,18 @@ spa_vdev_add(spa_t *spa, nvlist_t *nvroot) tvd = vd->vdev_child[c]; if (spa->spa_vdev_removal != NULL && tvd->vdev_ashift != spa->spa_max_ashift) { + dprintf("%s:%d: tvd->vdev_ashift = = %llu, " + "spa->spa_max_ashift = %d\n", __func__, + __LINE__, tvd->vdev_ashift, + spa->spa_max_ashift); return (spa_vdev_exit(spa, vd, txg, EINVAL)); } /* Fail if top level vdev is raidz or a dRAID */ - if (vdev_get_nparity(tvd) != 0) + if (vdev_get_nparity(tvd) != 0) { + dprintf("%s:%d: vdev_get_nparity(tvd) = %d\n", + __func__, __LINE__, vdev_get_nparity(tvd)); return (spa_vdev_exit(spa, vd, txg, EINVAL)); + } /* * Need the top level mirror to be @@ -6606,6 +6699,11 @@ spa_vdev_add(spa_t *spa, nvlist_t *nvroot) cid < tvd->vdev_children; cid++) { vdev_t *cvd = tvd->vdev_child[cid]; if (!cvd->vdev_ops->vdev_op_leaf) { + dprintf("%s:%d: cvd->" + "vdev_ops->vdev_op_leaf = " + "%d\n", __func__, __LINE__, + cvd->vdev_ops-> + vdev_op_leaf); return (spa_vdev_exit(spa, vd, txg, EINVAL)); } @@ -6669,6 +6767,7 @@ spa_vdev_add(spa_t *spa, nvlist_t *nvroot) spa_event_notify(spa, NULL, NULL, ESC_ZFS_VDEV_ADD); mutex_exit(&spa_namespace_lock); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -9437,23 +9536,34 @@ spa_lookup_by_guid(spa_t *spa, uint64_t guid, boolean_t aux) vdev_t *vd; int i; - if ((vd = vdev_lookup_by_guid(spa->spa_root_vdev, guid)) != NULL) + if ((vd = vdev_lookup_by_guid(spa->spa_root_vdev, guid)) != NULL) { + dprintf("%s:%d: Returning 0x%p\n", __func__, __LINE__, vd); return (vd); + } if (aux) { for (i = 0; i < spa->spa_l2cache.sav_count; i++) { vd = spa->spa_l2cache.sav_vdevs[i]; - if (vd->vdev_guid == guid) + if (vd->vdev_guid == guid) { + dprintf("%s:%d: vd->vdev_guid = %llu. " + "Returning 0x%p\n", __func__, + __LINE__, vd->vdev_guid, vd); return (vd); + } } for (i = 0; i < spa->spa_spares.sav_count; i++) { vd = spa->spa_spares.sav_vdevs[i]; - if (vd->vdev_guid == guid) + if (vd->vdev_guid == guid) { + dprintf("%s:%d: vd->vdev_guid = %llu. " + "Returning 0x%p\n", __func__, __LINE__, + vd->vdev_guid, vd); return (vd); + } } } + dprintf("%s:%d: Returning NULL\n", __func__, __LINE__); return (NULL); } @@ -9518,6 +9628,7 @@ spa_has_active_shared_spare(spa_t *spa) return (B_TRUE); } + dprintf("%s:%d: Returning FALSE\n", __func__, __LINE__); return (B_FALSE); } diff --git a/module/zfs/spa_history.c b/module/zfs/spa_history.c index dae06e46c316..aebc0c2dccfd 100644 --- a/module/zfs/spa_history.c +++ b/module/zfs/spa_history.c @@ -376,7 +376,9 @@ spa_history_log_nvl(spa_t *spa, nvlist_t *nvl) dmu_tx_t *tx; nvlist_t *nvarg, *in_nvl = NULL; - if (spa_version(spa) < SPA_VERSION_ZPOOL_HISTORY || !spa_writeable(spa)) + dprintf("%s: spa = 0x%p, nvl = 0x%p\n", __func__, spa, nvl); + if (spa_version(spa) < SPA_VERSION_ZPOOL_HISTORY || + !spa_writeable(spa)) return (SET_ERROR(EINVAL)); err = nvlist_lookup_nvlist(nvl, ZPOOL_HIST_INPUT_NVL, &in_nvl); @@ -388,6 +390,8 @@ spa_history_log_nvl(spa_t *spa, nvlist_t *nvl) err = dmu_tx_assign(tx, TXG_WAIT); if (err) { dmu_tx_abort(tx); + dprintf("%s:%d: Returning error %d\n", __func__, __LINE__, + err); return (err); } @@ -409,6 +413,7 @@ spa_history_log_nvl(spa_t *spa, nvlist_t *nvl) dmu_tx_commit(tx); /* spa_history_log_sync will free nvl */ + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } diff --git a/module/zfs/spa_misc.c b/module/zfs/spa_misc.c index 19a1613686e5..e4d8dc435666 100644 --- a/module/zfs/spa_misc.c +++ b/module/zfs/spa_misc.c @@ -583,6 +583,8 @@ spa_lookup(const char *name) ASSERT(MUTEX_HELD(&spa_namespace_lock)); + TraceEvent(5, "%s:%d: name = %s\n", __func__, __LINE__, + (name ? name : "NULL")); (void) strlcpy(search.spa_name, name, sizeof (search.spa_name)); /* @@ -595,6 +597,7 @@ spa_lookup(const char *name) spa = avl_find(&spa_namespace_avl, &search, &where); + TraceEvent(5, "%s:%d: Returning 0x%p\n", __func__, __LINE__, spa); return (spa); } @@ -996,6 +999,8 @@ spa_aux_exists(uint64_t guid, uint64_t *pool, int *refcnt, avl_tree_t *avl) { spa_aux_t search, *found; + dprintf("%s:%d: guid = %llu, pool = 0x%p, refcnt = 0x%p, avl = 0x%p\n", + __func__, __LINE__, guid, pool, refcnt, avl); search.aux_guid = guid; found = avl_find(avl, &search, NULL); @@ -1013,6 +1018,7 @@ spa_aux_exists(uint64_t guid, uint64_t *pool, int *refcnt, avl_tree_t *avl) *refcnt = 0; } + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, found != NULL); return (found != NULL); } @@ -1083,10 +1089,13 @@ spa_spare_exists(uint64_t guid, uint64_t *pool, int *refcnt) { boolean_t found; + dprintf("%s:%d guid = %llu, pool = 0x%p, refcnt = 0x%p\n", + __func__, __LINE__, guid, pool, refcnt); mutex_enter(&spa_spare_lock); found = spa_aux_exists(guid, pool, refcnt, &spa_spare_avl); mutex_exit(&spa_spare_lock); + dprintf("%s:%d Returning %d\n", __func__, __LINE__, found); return (found); } @@ -1136,10 +1145,13 @@ spa_l2cache_exists(uint64_t guid, uint64_t *pool) { boolean_t found; + dprintf("%s:%d: guid = %llu, pool = 0x%p\n", __func__, __LINE__, + guid, pool); mutex_enter(&spa_l2cache_lock); found = spa_aux_exists(guid, pool, NULL, &spa_l2cache_avl); mutex_exit(&spa_l2cache_lock); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, found); return (found); } @@ -1311,6 +1323,7 @@ spa_vdev_exit(spa_t *spa, vdev_t *vd, uint64_t txg, int error) mutex_exit(&spa_namespace_lock); mutex_exit(&spa->spa_vdev_top_lock); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1435,6 +1448,8 @@ spa_by_guid(uint64_t pool_guid, uint64_t device_guid) spa_t *spa; avl_tree_t *t = &spa_namespace_avl; + dprintf("%s:%d: pool_guid = %llu, device_guid = %llu\n", __func__, + __LINE__, pool_guid, device_guid); ASSERT(MUTEX_HELD(&spa_namespace_lock)); for (spa = avl_first(t); spa != NULL; spa = AVL_NEXT(t, spa)) { @@ -1461,6 +1476,7 @@ spa_by_guid(uint64_t pool_guid, uint64_t device_guid) } } + dprintf("%s:%d: Returning 0x%p\n", __func__, __LINE__, spa); return (spa); } diff --git a/module/zfs/space_map.c b/module/zfs/space_map.c index 11d4798925e4..b089666c5c66 100644 --- a/module/zfs/space_map.c +++ b/module/zfs/space_map.c @@ -101,8 +101,11 @@ space_map_iterate(space_map_t *sm, uint64_t end, sm_cb_t callback, void *arg) dmu_buf_t *db; error = dmu_buf_hold(sm->sm_os, space_map_object(sm), block_base, FTAG, &db, DMU_READ_PREFETCH); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + error); return (error); + } uint64_t *block_start = db->db_data; uint64_t block_length = MIN(end - block_base, blksz); @@ -187,6 +190,12 @@ space_map_iterate(space_map_t *sm, uint64_t end, sm_cb_t callback, void *arg) } dmu_buf_rele(db, FTAG); } + + if (error) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, + error); return (error); } @@ -409,6 +418,7 @@ space_map_load_callback(space_map_entry_t *sme, void *arg) range_tree_remove(smla->smla_rt, sme->sme_offset, sme->sme_run); } + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -436,6 +446,7 @@ space_map_load_length(space_map_t *sm, range_tree_t *rt, maptype_t maptype, if (err != 0) range_tree_vacate(rt, NULL, NULL); + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -797,11 +808,14 @@ space_map_open_impl(space_map_t *sm) u_longlong_t blocks; error = dmu_bonus_hold(sm->sm_os, sm->sm_object, sm, &sm->sm_dbuf); - if (error) + if (error) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); + } dmu_object_size_from_db(sm->sm_dbuf, &sm->sm_blksz, &blocks); sm->sm_phys = sm->sm_dbuf->db_data; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -830,10 +844,12 @@ space_map_open(space_map_t **smp, objset_t *os, uint64_t object, error = space_map_open_impl(sm); if (error != 0) { space_map_close(sm); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } *smp = sm; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } diff --git a/module/zfs/vdev.c b/module/zfs/vdev.c index 4e316d8135ee..b5b616d9337b 100644 --- a/module/zfs/vdev.c +++ b/module/zfs/vdev.c @@ -402,9 +402,13 @@ vdev_lookup_top(spa_t *spa, uint64_t vdev) if (vdev < rvd->vdev_children) { ASSERT(rvd->vdev_child[vdev] != NULL); + TraceEvent(8, "%s:%d: vdev = %llu, rvd->vdev_children = %llu." + " Returning 0x%p", __func__, __LINE__, vdev, + rvd->vdev_children, rvd->vdev_child[vdev]); return (rvd->vdev_child[vdev]); } + dprintf("%s:%d: Returning NULL\n", __func__, __LINE__); return (NULL); } @@ -413,14 +417,21 @@ vdev_lookup_by_guid(vdev_t *vd, uint64_t guid) { vdev_t *mvd; - if (vd->vdev_guid == guid) + if (vd->vdev_guid == guid) { + dprintf("%s:%d: vd->vdev_guid = %llu. Returning 0x%p\n", + __func__, __LINE__, vd->vdev_guid, vd); return (vd); + } for (int c = 0; c < vd->vdev_children; c++) if ((mvd = vdev_lookup_by_guid(vd->vdev_child[c], guid)) != - NULL) + NULL) { + dprintf("%s:%d: Returning 0x%p\n", __func__, __LINE__, + mvd); return (mvd); + } + dprintf("%s:%d: Returning NULL\n", __func__, __LINE__); return (NULL); } @@ -1647,11 +1658,15 @@ vdev_probe(vdev_t *vd, zio_t *zio) ASSERT(vd->vdev_ops->vdev_op_leaf); + dprintf("%s:%d: vd = 0x%p, zio = 0x%p\n", __func__, __LINE__, vd, zio); /* * Don't probe the probe. */ - if (zio && (zio->io_flags & ZIO_FLAG_PROBE)) + if (zio && (zio->io_flags & ZIO_FLAG_PROBE)) { + dprintf("%s:%d: zio->io_flags = %llu. Returning NULL\n", + __func__, __LINE__, zio->io_flags); return (NULL); + } /* * To prevent 'probe storms' when a device fails, we create @@ -1710,6 +1725,7 @@ vdev_probe(vdev_t *vd, zio_t *zio) if (vps == NULL) { ASSERT(zio != NULL); + dprintf("%s:%d: Returning NULL\n", __func__, __LINE__); return (NULL); } @@ -1722,10 +1738,13 @@ vdev_probe(vdev_t *vd, zio_t *zio) ZIO_PRIORITY_SYNC_READ, vps->vps_flags, B_TRUE)); } - if (zio == NULL) + if (zio == NULL) { + dprintf("%s:%d: Returning 0x%p\n", __func__, __LINE__, pio); return (pio); + } zio_nowait(pio); + dprintf("%s:%d: Returning NULL\n", __func__, __LINE__); return (NULL); } @@ -1886,6 +1905,8 @@ vdev_open(vdev_t *vd) uint64_t logical_ashift = 0; uint64_t physical_ashift = 0; + dprintf("%s:%d: vd = 0x%p\n", __func__, __LINE__, vd); + ASSERT(vd->vdev_open_thread == curthread || spa_config_held(spa, SCL_STATE_ALL, RW_WRITER) == SCL_STATE_ALL); ASSERT(vd->vdev_state == VDEV_STATE_CLOSED || @@ -1947,6 +1968,8 @@ vdev_open(vdev_t *vd) vdev_set_state(vd, B_TRUE, VDEV_STATE_CANT_OPEN, vd->vdev_stat.vs_aux); } + + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1976,8 +1999,10 @@ vdev_open(vdev_t *vd) /* * For hole or missing vdevs we just return success. */ - if (vd->vdev_ishole || vd->vdev_ops == &vdev_missing_ops) + if (vd->vdev_ishole || vd->vdev_ops == &vdev_missing_ops) { + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } for (int c = 0; c < vd->vdev_children; c++) { if (vd->vdev_child[c]->vdev_state != VDEV_STATE_HEALTHY) { @@ -2117,6 +2142,7 @@ vdev_open(vdev_t *vd) (error = zio_wait(vdev_probe(vd, NULL))) != 0) { vdev_set_state(vd, B_TRUE, VDEV_STATE_FAULTED, VDEV_AUX_ERR_EXCEEDED); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -2138,6 +2164,7 @@ vdev_open(vdev_t *vd) if (vd->vdev_ops->vdev_op_leaf && !spa->spa_scrub_reopen) dsl_scan_assess_vdev(spa->spa_dsl_pool, vd); + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -2621,6 +2648,7 @@ vdev_create(vdev_t *vd, uint64_t txg, boolean_t isreplacing) (error = vdev_label_init(vd, txg, isreplacing ? VDEV_LABEL_REPLACE : VDEV_LABEL_CREATE)) != 0) { vdev_close(vd); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -2814,6 +2842,7 @@ vdev_dtl_empty(vdev_t *vd, vdev_dtl_type_t t) empty = range_tree_is_empty(rt); mutex_exit(&vd->vdev_dtl_lock); + dprintf("%s:%d: t = %d. Returning %d\n", __func__, __LINE__, t, empty); return (empty); } @@ -3121,8 +3150,11 @@ vdev_dtl_load(vdev_t *vd) error = space_map_open(&vd->vdev_dtl_sm, mos, vd->vdev_dtl_object, 0, -1ULL, 0); - if (error) + if (error) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + error); return (error); + } ASSERT(vd->vdev_dtl_sm != NULL); rt = range_tree_create(NULL, RANGE_SEG64, NULL, 0, 0); @@ -3137,6 +3169,7 @@ vdev_dtl_load(vdev_t *vd) range_tree_vacate(rt, NULL, NULL); range_tree_destroy(rt); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -3146,6 +3179,7 @@ vdev_dtl_load(vdev_t *vd) break; } + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } diff --git a/module/zfs/vdev_label.c b/module/zfs/vdev_label.c index 04202a9f8960..0a0f7cf55e3f 100644 --- a/module/zfs/vdev_label.c +++ b/module/zfs/vdev_label.c @@ -766,8 +766,10 @@ vdev_label_read_config(vdev_t *vd, uint64_t txg) ASSERT(vd->vdev_validate_thread == curthread || spa_config_held(spa, SCL_STATE_ALL, RW_WRITER) == SCL_STATE_ALL); - if (!vdev_readable(vd)) + if (!vdev_readable(vd)) { + dprintf("%s:%d: Returning NULL\n", __func__, __LINE__); return (NULL); + } /* * The label for a dRAID distributed spare is not stored on disk. @@ -841,6 +843,7 @@ vdev_label_read_config(vdev_t *vd, uint64_t txg) abd_free(vp_abd[l]); } + dprintf("%s:%d: Returning 0x%p\n", __func__, __LINE__, config); return (config); } @@ -865,8 +868,10 @@ vdev_inuse(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason, /* * Read the label, if any, and perform some basic sanity checks. */ - if ((label = vdev_label_read_config(vd, -1ULL)) == NULL) + if ((label = vdev_label_read_config(vd, -1ULL)) == NULL) { + dprintf("%s:%d: Returning FALSE\n", __func__, __LINE__); return (B_FALSE); + } (void) nvlist_lookup_uint64(label, ZPOOL_CONFIG_CREATE_TXG, &vdtxg); @@ -876,6 +881,7 @@ vdev_inuse(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason, nvlist_lookup_uint64(label, ZPOOL_CONFIG_GUID, &device_guid) != 0) { nvlist_free(label); + dprintf("%s:%d: Returning FALSE\n", __func__, __LINE__); return (B_FALSE); } @@ -885,6 +891,8 @@ vdev_inuse(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason, nvlist_lookup_uint64(label, ZPOOL_CONFIG_POOL_TXG, &txg) != 0)) { nvlist_free(label); + dprintf("%s:%d: state = %llu. Returning FALSE\n", __func__, + __LINE__, state); return (B_FALSE); } @@ -898,8 +906,11 @@ vdev_inuse(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason, if (state != POOL_STATE_SPARE && state != POOL_STATE_L2CACHE && !spa_guid_exists(pool_guid, device_guid) && !spa_spare_exists(device_guid, NULL, NULL) && - !spa_l2cache_exists(device_guid, NULL)) + !spa_l2cache_exists(device_guid, NULL)) { + dprintf("%s:%d: state = %llu. Returning FALSE\n", __func__, + __LINE__, state); return (B_FALSE); + } /* * If the transaction group is zero, then this an initialized (but @@ -909,8 +920,12 @@ vdev_inuse(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason, * transaction. */ if (state != POOL_STATE_SPARE && state != POOL_STATE_L2CACHE && - txg == 0 && vdtxg == crtxg) + txg == 0 && vdtxg == crtxg) { + dprintf("%s:%d: state = %llu, txg = %llu, vdtxg = %llu, " + "crtxg = %llu. Returning TRUE\n", __func__, __LINE__, + state, txg, vdtxg, crtxg); return (B_TRUE); + } /* * Check to see if this is a spare device. We do an explicit check for @@ -941,8 +956,10 @@ vdev_inuse(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason, /* * Check to see if this is an l2cache device. */ - if (spa_l2cache_exists(device_guid, NULL)) + if (spa_l2cache_exists(device_guid, NULL)) { + dprintf("%s:%d: Returning TRUE\n", __func__, __LINE__); return (B_TRUE); + } /* * We can't rely on a pool's state if it's been imported @@ -951,13 +968,19 @@ vdev_inuse(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason, */ if (state != POOL_STATE_SPARE && state != POOL_STATE_L2CACHE && (spa = spa_by_guid(pool_guid, device_guid)) != NULL && - spa_mode(spa) == SPA_MODE_READ) + spa_mode(spa) == SPA_MODE_READ) { + dprintf("%s:%d: state = %llu, spa = 0x%p\n", __func__, + __LINE__, state, spa); state = POOL_STATE_ACTIVE; + } /* * If the device is marked ACTIVE, then this device is in use by another * pool on the system. */ + + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + state == POOL_STATE_ACTIVE); return (state == POOL_STATE_ACTIVE); } @@ -990,14 +1013,20 @@ vdev_label_init(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason) for (int c = 0; c < vd->vdev_children; c++) if ((error = vdev_label_init(vd->vdev_child[c], - crtxg, reason)) != 0) + crtxg, reason)) != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + error); return (error); + } /* Track the creation time for this vdev */ vd->vdev_crtxg = crtxg; - if (!vd->vdev_ops->vdev_op_leaf || !spa_writeable(spa)) + if (!vd->vdev_ops->vdev_op_leaf || !spa_writeable(spa)) { + dprintf("%s:%d: vd->vdev_ops->vdev_op_leaf = %d. Returning " + "0\n", __func__, __LINE__, vd->vdev_ops->vdev_op_leaf); return (0); + } /* * Dead vdevs cannot be initialized. @@ -1052,8 +1081,10 @@ vdev_label_init(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason) * rest of the code. If we're adding an l2cache, then it's * already labeled appropriately and we can just return. */ - if (reason == VDEV_LABEL_L2CACHE) + if (reason == VDEV_LABEL_L2CACHE) { + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (0); + } ASSERT(reason == VDEV_LABEL_REPLACE); } @@ -1194,6 +1225,7 @@ vdev_label_init(vdev_t *vd, uint64_t crtxg, vdev_labeltype_t reason) spa_l2cache_exists(vd->vdev_guid, NULL))) spa_l2cache_add(vd); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } diff --git a/module/zfs/vdev_removal.c b/module/zfs/vdev_removal.c index f762c1df96aa..3a4627110e16 100644 --- a/module/zfs/vdev_removal.c +++ b/module/zfs/vdev_removal.c @@ -1627,6 +1627,8 @@ spa_vdev_remove_cancel_check(void *arg, dmu_tx_t *tx) if (spa->spa_vdev_removal == NULL) return (ENOTACTIVE); + + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1788,7 +1790,7 @@ spa_vdev_remove_cancel_impl(spa_t *spa) metaslab_group_activate(vd->vdev_log_mg); spa_config_exit(spa, SCL_ALLOC | SCL_VDEV, FTAG); } - + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1862,6 +1864,7 @@ spa_vdev_remove_log(vdev_t *vd, uint64_t *txg) spa_t *spa = vd->vdev_spa; int error = 0; + dprintf("%s:%d: vd = 0x%p, txg = 0x%p\n", __func__, __LINE__, vd, txg); ASSERT(vd->vdev_islog); ASSERT(vd == vd->vdev_top); ASSERT3P(vd->vdev_log_mg, ==, NULL); @@ -1901,6 +1904,7 @@ spa_vdev_remove_log(vdev_t *vd, uint64_t *txg) if (error != 0) { metaslab_group_activate(mg); ASSERT3P(vd->vdev_log_mg, ==, NULL); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } ASSERT0(vd->vdev_stat.vs_alloc); @@ -2040,9 +2044,8 @@ spa_vdev_remove_top_check(vdev_t *vd) /* * All vdevs in normal class must have the same ashift. */ - if (spa->spa_max_ashift != spa->spa_min_ashift) { + if (spa->spa_max_ashift != spa->spa_min_ashift) return (SET_ERROR(EINVAL)); - } /* * A removed special/dedup vdev must have same ashift as normal class. @@ -2087,8 +2090,9 @@ spa_vdev_remove_top_check(vdev_t *vd) for (uint64_t cid = 0; cid < cvd->vdev_children; cid++) { if (!cvd->vdev_child[cid]->vdev_ops-> - vdev_op_leaf) + vdev_op_leaf) { return (SET_ERROR(EINVAL)); + } } } } @@ -2116,9 +2120,10 @@ spa_vdev_remove_top(vdev_t *vd, uint64_t *txg) * are errors. */ error = spa_vdev_remove_top_check(vd); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); - + } /* * Stop allocating from this vdev. Note that we must check * that this is not the only device in the pool before @@ -2172,6 +2177,8 @@ spa_vdev_remove_top(vdev_t *vd, uint64_t *txg) spa_async_request(spa, SPA_ASYNC_INITIALIZE_RESTART); spa_async_request(spa, SPA_ASYNC_TRIM_RESTART); spa_async_request(spa, SPA_ASYNC_AUTOTRIM_RESTART); + dprintf("%s:%d: spa_vdev_remove_top_check returned %d\n", + __func__, __LINE__, error); return (error); } @@ -2184,6 +2191,7 @@ spa_vdev_remove_top(vdev_t *vd, uint64_t *txg) vdev_remove_initiate_sync, (void *)(uintptr_t)vd->vdev_id, tx); dmu_tx_commit(tx); + TraceEvent(5, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -2208,6 +2216,8 @@ spa_vdev_remove(spa_t *spa, uint64_t guid, boolean_t unspare) sysevent_t *ev = NULL; char *vd_type = NULL, *vd_path = NULL; + dprintf("%s:%d: spa = 0x%p, guid = %llu, unspare = %d\n", + __func__, __LINE__, spa, guid, unspare); ASSERT(spa_writeable(spa)); if (!locked) @@ -2221,6 +2231,8 @@ spa_vdev_remove(spa_t *spa, uint64_t guid, boolean_t unspare) if (!locked) return (spa_vdev_exit(spa, NULL, txg, error)); + dprintf("%s:%d: Returning error = %d\n", __func__, __LINE__, + error); return (error); } @@ -2330,6 +2342,7 @@ spa_vdev_remove(spa_t *spa, uint64_t guid, boolean_t unspare) if (ev != NULL) spa_event_post(ev); + dprintf("%s:%d: Returning 0\n", __func__, __LINE__); return (error); } diff --git a/module/zfs/zap.c b/module/zfs/zap.c index 6f03beef3bdb..6c2d12f98339 100644 --- a/module/zfs/zap.c +++ b/module/zfs/zap.c @@ -256,11 +256,16 @@ zap_table_store(zap_t *zap, zap_table_phys_t *tbl, uint64_t idx, uint64_t val, uint64_t blk = idx >> (bs-3); uint64_t off = idx & ((1<<(bs-3))-1); + TraceEvent(8, "%s:%d:zap = 0x%p, tbl = 0x%p, idx = %llu, val = %llu\n", + __func__, __LINE__, zap, tbl, idx, val); + dmu_buf_t *db; int err = dmu_buf_hold(zap->zap_objset, zap->zap_object, (tbl->zt_blk + blk) << bs, FTAG, &db, DMU_READ_NO_PREFETCH); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } dmu_buf_will_dirty(db, tx); if (tbl->zt_nextblk != 0) { @@ -274,6 +279,8 @@ zap_table_store(zap_t *zap, zap_table_phys_t *tbl, uint64_t idx, uint64_t val, DMU_READ_NO_PREFETCH); if (err != 0) { dmu_buf_rele(db, FTAG); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); } dmu_buf_will_dirty(db2, tx); @@ -522,6 +529,9 @@ zap_get_leaf_byblk(zap_t *zap, uint64_t blkid, dmu_tx_t *tx, krw_t lt, { dmu_buf_t *db; + TraceEvent(8, "%s:%d: zap = 0x%p, blkid = %llu, tx = 0x%p, lt = %d, " + "lp = 0x%p\n", __func__, __LINE__, zap, blkid, tx, lt, lp); + ASSERT(RW_LOCK_HELD(&zap->zap_rwlock)); /* @@ -539,8 +549,10 @@ zap_get_leaf_byblk(zap_t *zap, uint64_t blkid, dmu_tx_t *tx, krw_t lt, int err = dmu_buf_hold_by_dnode(dn, blkid << bs, NULL, &db, DMU_READ_NO_PREFETCH); dmu_buf_dnode_exit(zap->zap_dbuf); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } ASSERT3U(db->db_object, ==, zap->zap_object); ASSERT3U(db->db_offset, ==, blkid << bs); @@ -565,6 +577,7 @@ zap_get_leaf_byblk(zap_t *zap, uint64_t blkid, dmu_tx_t *tx, krw_t lt, ASSERT3U(zap_leaf_phys(l)->l_hdr.lh_magic, ==, ZAP_LEAF_MAGIC); *lp = l; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -577,6 +590,7 @@ zap_idx_to_blk(zap_t *zap, uint64_t idx, uint64_t *valp) ASSERT3U(idx, <, (1ULL << zap_f_phys(zap)->zap_ptrtbl.zt_shift)); *valp = ZAP_EMBEDDED_PTRTBL_ENT(zap, idx); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } else { return (zap_table_load(zap, &zap_f_phys(zap)->zap_ptrtbl, @@ -616,13 +630,21 @@ zap_deref_leaf(zap_t *zap, uint64_t h, dmu_tx_t *tx, krw_t lt, zap_leaf_t **lp) uint64_t idx = ZAP_HASH_IDX(h, zap_f_phys(zap)->zap_ptrtbl.zt_shift); int err = zap_idx_to_blk(zap, idx, &blk); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } err = zap_get_leaf_byblk(zap, blk, tx, lt, lp); ASSERT(err || ZAP_HASH_IDX(h, zap_leaf_phys(*lp)->l_hdr.lh_prefix_len) == zap_leaf_phys(*lp)->l_hdr.lh_prefix); + + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); } @@ -754,6 +776,8 @@ fzap_checkname(zap_name_t *zn) { if (zn->zn_key_orig_numints * zn->zn_key_intlen > ZAP_MAXNAMELEN) return (SET_ERROR(ENAMETOOLONG)); + + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -798,12 +822,18 @@ fzap_lookup(zap_name_t *zn, zap_entry_handle_t zeh; int err = fzap_checkname(zn); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning err = %d\n", __func__, __LINE__, + err); return (err); + } err = zap_deref_leaf(zn->zn_zap, zn->zn_hash, NULL, RW_READER, &l); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning err = %d\n", __func__, __LINE__, + err); return (err); + } err = zap_leaf_lookup(l, zn, &zeh); if (err == 0) { if ((err = fzap_checksize(integer_size, num_integers)) != 0) { @@ -820,6 +850,8 @@ fzap_lookup(zap_name_t *zn, } zap_put_leaf(l); + + TraceEvent(5, "%s:%d: Returning err = %d\n", __func__, __LINE__, err); return (err); } @@ -1037,6 +1069,7 @@ zap_value_search(objset_t *os, uint64_t zapobj, uint64_t value, uint64_t mask, } zap_cursor_fini(&zc); kmem_free(za, sizeof (*za)); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -1248,8 +1281,11 @@ fzap_cursor_retrieve(zap_t *zap, zap_cursor_t *zc, zap_attribute_t *za) if (zc->zc_leaf == NULL) { err = zap_deref_leaf(zap, zc->zc_hash, NULL, RW_READER, &zc->zc_leaf); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: zap_deref_leaf returning %d\n", + __func__, __LINE__, err); return (err); + } } else { rw_enter(&zc->zc_leaf->l_rwlock, RW_READER); } @@ -1298,6 +1334,7 @@ fzap_cursor_retrieve(zap_t *zap, zap_cursor_t *zc, zap_attribute_t *za) NULL, za->za_name, zap); } rw_exit(&zc->zc_leaf->l_rwlock); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } diff --git a/module/zfs/zap_leaf.c b/module/zfs/zap_leaf.c index aa6c298c3b4b..ccf103d8c763 100644 --- a/module/zfs/zap_leaf.c +++ b/module/zfs/zap_leaf.c @@ -422,7 +422,8 @@ zap_leaf_lookup(zap_leaf_t *l, zap_name_t *zn, zap_entry_handle_t *zeh) return (0); } } - + TraceEvent(8, "%s:%d: Returning ENOENT = %d\n", __func__, __LINE__, + ENOENT); return (SET_ERROR(ENOENT)); } @@ -487,6 +488,8 @@ zap_entry_read(const zap_entry_handle_t *zeh, if (zeh->zeh_num_integers > num_integers) return (SET_ERROR(EOVERFLOW)); + + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -506,8 +509,13 @@ zap_entry_read_name(zap_t *zap, const zap_entry_handle_t *zeh, uint16_t buflen, zap_leaf_array_read(zeh->zeh_leaf, le->le_name_chunk, 1, le->le_name_numints, 1, buflen, buf); } - if (le->le_name_numints > buflen) + if (le->le_name_numints > buflen) { + TraceEvent(8, "%s:%d: le->le_name_numints = %d, buflen = %d. " + "Returning EOVERFLOW = %d\n", __func__, __LINE__, + le->le_name_numints, buflen, EOVERFLOW); return (SET_ERROR(EOVERFLOW)); + } + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -606,8 +614,11 @@ zap_entry_create(zap_leaf_t *l, zap_name_t *zn, uint32_t cd, ASSERT3U(cd, <, zap_maxcd(zn->zn_zap)); } - if (zap_leaf_phys(l)->l_hdr.lh_nfree < numchunks) + if (zap_leaf_phys(l)->l_hdr.lh_nfree < numchunks) { + TraceEvent(8, "%s:%d: Returning error %d\n", __func__, + __LINE__, EAGAIN); return (SET_ERROR(EAGAIN)); + } /* make the entry */ chunk = zap_leaf_chunk_alloc(l); diff --git a/module/zfs/zap_micro.c b/module/zfs/zap_micro.c index 5432a6403e74..690e1f5f0797 100644 --- a/module/zfs/zap_micro.c +++ b/module/zfs/zap_micro.c @@ -205,6 +205,8 @@ zap_name_alloc(zap_t *zap, const char *key, matchtype_t mt) } else { if (mt != 0) { zap_name_free(zn); + dprintf("%s:%d: Returning null mt:%d\n", __func__, + __LINE__, mt); return (NULL); } zn->zn_key_norm = zn->zn_key_orig; @@ -515,6 +517,9 @@ zap_lockdir_impl(dmu_buf_t *db, void *tag, dmu_tx_t *tx, *zapp = NULL; + TraceEvent(8, "%s:%d: db = 0x%p, tag = 0x%p, tx = 0x%p, lti = %d, " + "fatreader = %d, adding = %d, zapp = 0x%p\n", + __func__, __LINE__, db, tag, tx, lti, fatreader, adding, zapp); dmu_object_info_from_db(db, &doi); if (DMU_OT_BYTESWAP(doi.doi_type) != DMU_BSWAP_ZAP) return (SET_ERROR(EINVAL)); @@ -568,6 +573,8 @@ zap_lockdir_impl(dmu_buf_t *db, void *tag, dmu_tx_t *tx, int err = mzap_upgrade(zapp, tag, tx, 0); if (err != 0) rw_exit(&zap->zap_rwlock); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); } VERIFY0(dmu_object_set_blocksize(os, obj, newsz, 0, tx)); @@ -576,6 +583,7 @@ zap_lockdir_impl(dmu_buf_t *db, void *tag, dmu_tx_t *tx, } *zapp = zap; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -587,6 +595,7 @@ zap_lockdir_by_dnode(dnode_t *dn, dmu_tx_t *tx, int err = dmu_buf_hold_by_dnode(dn, 0, tag, &db, DMU_READ_NO_PREFETCH); if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } #ifdef ZFS_DEBUG @@ -601,6 +610,12 @@ zap_lockdir_by_dnode(dnode_t *dn, dmu_tx_t *tx, if (err != 0) { dmu_buf_rele(db, tag); } + + if (err) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); } @@ -611,8 +626,11 @@ zap_lockdir(objset_t *os, uint64_t obj, dmu_tx_t *tx, dmu_buf_t *db; int err = dmu_buf_hold(os, obj, 0, tag, &db, DMU_READ_NO_PREFETCH); - if (err != 0) + if (err != 0) { + TraceEvent(5, "%s:%d: Returning %d\n", __func__, __LINE__, + err); return (err); + } #ifndef _WIN32 // Triggers under Windows, so until we can figure it out... #ifdef ZFS_DEBUG @@ -658,8 +676,8 @@ mzap_upgrade(zap_t **zapp, void *tag, dmu_tx_t *tx, zap_flags_t flags) } } - dprintf("upgrading obj=%llu with %u chunks\n", - (u_longlong_t)zap->zap_object, nchunks); + dprintf("%s:%d upgrading obj=%llu with %u chunks\n", __func__, + __LINE__, (u_longlong_t)zap->zap_object, nchunks); /* XXX destroy the avl later, so we can use the stored hash value */ mze_destroy(zap); @@ -669,7 +687,7 @@ mzap_upgrade(zap_t **zapp, void *tag, dmu_tx_t *tx, zap_flags_t flags) mzap_ent_phys_t *mze = &mzp->mz_chunk[i]; if (mze->mze_name[0] == 0) continue; - dprintf("adding %s=%llu\n", + dprintf("%s:%d adding %s=%llu\n", __func__, __LINE__, mze->mze_name, (u_longlong_t)mze->mze_value); zap_name_t *zn = zap_name_alloc(zap, mze->mze_name, 0); /* If we fail here, we would end up losing entries */ @@ -789,9 +807,11 @@ zap_create_claim_norm_dnsize(objset_t *os, uint64_t obj, int normflags, ASSERT3U(DMU_OT_BYTESWAP(ot), ==, DMU_BSWAP_ZAP); error = dmu_object_claim_dnsize(os, obj, ot, 0, bonustype, bonuslen, dnodesize, tx); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Returning error %d\n", __func__, __LINE__, + error); return (error); - + } error = dnode_hold(os, obj, FTAG, &dn); if (error != 0) return (error); @@ -903,8 +923,11 @@ zap_count(objset_t *os, uint64_t zapobj, uint64_t *count) int err = zap_lockdir(os, zapobj, NULL, RW_READER, TRUE, FALSE, FTAG, &zap); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: zap_lockdir returned with %d\n", __func__, + __LINE__, err); return (err); + } if (!zap->zap_ismicro) { err = fzap_count(zap, count); } else { @@ -1003,6 +1026,7 @@ zap_lookup_impl(zap_t *zap, const char *name, } } zap_name_free(zn); + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -1016,11 +1040,14 @@ zap_lookup_norm(objset_t *os, uint64_t zapobj, const char *name, int err = zap_lockdir(os, zapobj, NULL, RW_READER, TRUE, FALSE, FTAG, &zap); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); + } err = zap_lookup_impl(zap, name, integer_size, num_integers, buf, mt, realname, rn_len, ncp); zap_unlockdir(zap, FTAG); + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -1124,6 +1151,8 @@ zap_contains(objset_t *os, uint64_t zapobj, const char *name) 0, NULL, 0, NULL, 0, NULL); if (err == EOVERFLOW || err == EINVAL) err = 0; /* found, but skipped reading the value */ + + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } @@ -1565,8 +1594,11 @@ zap_cursor_retrieve(zap_cursor_t *zc, zap_attribute_t *za) int hb; err = zap_lockdir(zc->zc_objset, zc->zc_zapobj, NULL, RW_READER, TRUE, FALSE, NULL, &zc->zc_zap); - if (err != 0) + if (err != 0) { + dprintf("%s:%d: zap_lockdir returned %d\n", __func__, + __LINE__, err); return (err); + } /* * To support zap_cursor_init_serialized, advance, retrieve, @@ -1609,13 +1641,19 @@ zap_cursor_retrieve(zap_cursor_t *zc, zap_attribute_t *za) sizeof (za->za_name)); zc->zc_hash = mze->mze_hash; zc->zc_cd = mze->mze_cd; + TraceEvent(8, "%s:%d: Setting err = 0\n", __func__, + __LINE__); err = 0; } else { zc->zc_hash = -1ULL; + TraceEvent(5, "%s:%d: Setting err ENOENT = %d\n", + __func__, __LINE__, ENOENT); err = SET_ERROR(ENOENT); + } } rw_exit(&zc->zc_zap->zap_rwlock); + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, err); return (err); } diff --git a/module/zfs/zcp.c b/module/zfs/zcp.c index f724b44baf1d..da295ebbf5bb 100644 --- a/module/zfs/zcp.c +++ b/module/zfs/zcp.c @@ -588,6 +588,7 @@ zcp_nvpair_value_to_lua(lua_State *state, nvpair_t *pair, return (SET_ERROR(EINVAL)); } } + dprintf("%s:%d Returning error %d", __func__, __LINE__, err); return (err); } @@ -1045,6 +1046,7 @@ zcp_eval(const char *poolname, const char *program, boolean_t sync, if (instrlimit > zfs_lua_max_instrlimit) return (SET_ERROR(EINVAL)); + if (memlimit == 0 || memlimit > zfs_lua_max_memlimit) return (SET_ERROR(EINVAL)); diff --git a/module/zfs/zfeature.c b/module/zfs/zfeature.c index 9d16fff81d0a..d04a9d595c0f 100644 --- a/module/zfs/zfeature.c +++ b/module/zfs/zfeature.c @@ -236,9 +236,12 @@ feature_get_refcount(spa_t *spa, zfeature_info_t *feature, uint64_t *res) ASSERT(VALID_FEATURE_FID(feature->fi_feature)); if (spa->spa_feat_refcount_cache[feature->fi_feature] == SPA_FEATURE_DISABLED) { + TraceEvent(5, "%s:%d: Returning ENOTSUP = %d\n", __func__, + __LINE__, ENOTSUP); return (SET_ERROR(ENOTSUP)); } *res = spa->spa_feat_refcount_cache[feature->fi_feature]; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -478,8 +481,12 @@ spa_feature_is_enabled(spa_t *spa, spa_feature_t fid) uint64_t refcount = 0; ASSERT(VALID_FEATURE_FID(fid)); - if (spa_version(spa) < SPA_VERSION_FEATURES) + if (spa_version(spa) < SPA_VERSION_FEATURES) { + dprintf("%s:%d: spa->spa_ubsync.ub_version = %llu. " + "Returning False\n", __func__, __LINE__, + spa->spa_ubsync.ub_version); return (B_FALSE); + } err = feature_get_refcount(spa, &spa_feature_table[fid], &refcount); ASSERT(err == 0 || err == ENOTSUP); @@ -493,11 +500,16 @@ spa_feature_is_active(spa_t *spa, spa_feature_t fid) uint64_t refcount = 0; ASSERT(VALID_FEATURE_FID(fid)); - if (spa_version(spa) < SPA_VERSION_FEATURES) + if (spa_version(spa) < SPA_VERSION_FEATURES) { + dprintf("%s:%d: spa_version(spa) = %llu. Returning FALSE\n", + __func__, __LINE__, spa->spa_ubsync.ub_version); return (B_FALSE); + } err = feature_get_refcount(spa, &spa_feature_table[fid], &refcount); ASSERT(err == 0 || err == ENOTSUP); + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, + (err == 0 && refcount > 0)); return (err == 0 && refcount > 0); } diff --git a/module/zfs/zfs_ioctl.c b/module/zfs/zfs_ioctl.c index 4168c0e3b5a4..84287ecfcd76 100644 --- a/module/zfs/zfs_ioctl.c +++ b/module/zfs/zfs_ioctl.c @@ -1281,6 +1281,8 @@ get_nvlist(uint64_t nvl, uint64_t size, int iflag, nvlist_t **nvp) int error; nvlist_t *list = NULL; + TraceEvent(5, "%s:%d: nvl = %lu, size = %lu, iflag = %d, nvp = 0x%p\n", + __func__, __LINE__, nvl, size, iflag, nvp); /* * Read in and unpack the user-supplied nvlist. */ @@ -1297,12 +1299,15 @@ get_nvlist(uint64_t nvl, uint64_t size, int iflag, nvlist_t **nvp) if ((error = nvlist_unpack(packed, size, &list, 0)) != 0) { vmem_free(packed, size); + dprintf("%s:%d: Returning error %d\n", __func__, __LINE__, + error); return (error); } vmem_free(packed, size); *nvp = list; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1317,6 +1322,8 @@ nvlist_smush(nvlist_t *errors, size_t max) { size_t size; + dprintf("%s:%d: errors = 0x%p, max = %llu\n", __func__, __LINE__, + errors, max); size = fnvlist_size(errors); if (size > max) { @@ -1341,7 +1348,7 @@ nvlist_smush(nvlist_t *errors, size_t max) fnvlist_add_int32(errors, ZPROP_N_MORE_ERRORS, n); ASSERT3U(fnvlist_size(errors), <=, max); } - + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -1354,11 +1361,13 @@ put_nvlist(zfs_cmd_t *zc, nvlist_t *nvl) size = fnvlist_size(nvl); + TraceEvent(8, "ZFS: %s trying copyout %p:%d (max)\n", __func__, + zc->zc_nvlist_dst, zc->zc_nvlist_dst_size); if (size > zc->zc_nvlist_dst_size) { error = SET_ERROR(ENOMEM); } else { packed = fnvlist_pack(nvl, &size); - if (ddi_copyout(packed, (void *)(uintptr_t)zc->zc_nvlist_dst, + if (ddi_copyout(packed, (void*)(uintptr_t)zc->zc_nvlist_dst, size, zc->zc_iflags) != 0) error = SET_ERROR(EFAULT); fnvlist_pack_free(packed, size); @@ -1366,6 +1375,7 @@ put_nvlist(zfs_cmd_t *zc, nvlist_t *nvl) zc->zc_nvlist_dst_size = size; zc->zc_nvlist_dst_filled = B_TRUE; + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1455,6 +1465,8 @@ zfs_ioc_pool_create(zfs_cmd_t *zc) const char *spa_name = zc->zc_name; boolean_t unload_wkey = B_TRUE; + dprintf("%s:%d: zc = 0x%p\n", __func__, __LINE__, zc); + if ((error = get_nvlist(zc->zc_nvlist_conf, zc->zc_nvlist_conf_size, zc->zc_iflags, &config))) return (error); @@ -1463,6 +1475,8 @@ zfs_ioc_pool_create(zfs_cmd_t *zc) get_nvlist(zc->zc_nvlist_src, zc->zc_nvlist_src_size, zc->zc_iflags, &props))) { nvlist_free(config); + dprintf("%s:%d: Returning with %d\n", __func__, __LINE__, + error); return (error); } @@ -1481,8 +1495,11 @@ zfs_ioc_pool_create(zfs_cmd_t *zc) (void) nvlist_lookup_nvlist(props, ZPOOL_ROOTFS_PROPS, &nvl); if (nvl) { error = nvlist_dup(nvl, &rootprops, KM_SLEEP); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Returning with %d\n", __func__, + __LINE__, error); goto pool_props_bad; + } (void) nvlist_remove_all(props, ZPOOL_ROOTFS_PROPS); } @@ -1490,15 +1507,21 @@ zfs_ioc_pool_create(zfs_cmd_t *zc) &hidden_args); error = dsl_crypto_params_create_nvlist(DCP_CMD_NONE, rootprops, hidden_args, &dcp); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Returning with %d\n", __func__, + __LINE__, error); goto pool_props_bad; + } (void) nvlist_remove_all(props, ZPOOL_HIDDEN_ARGS); VERIFY(nvlist_alloc(&zplprops, NV_UNIQUE_NAME, KM_SLEEP) == 0); error = zfs_fill_zplprops_root(version, rootprops, zplprops, NULL); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Setting error = %d\n", __func__, + __LINE__, error); goto pool_props_bad; + } if (nvlist_lookup_string(props, zpool_prop_to_name(ZPOOL_PROP_TNAME), &tname) == 0) @@ -1512,6 +1535,9 @@ zfs_ioc_pool_create(zfs_cmd_t *zc) */ if (!error && (error = zfs_set_prop_nvlist(spa_name, ZPROP_SRC_LOCAL, rootprops, NULL)) != 0) { + dprintf("%s:%d: zfs_set_prop_nvlist returned with %d\n", + __func__, __LINE__, error); + (void) spa_destroy(zc->zc_name); (void) spa_destroy(spa_name); unload_wkey = B_FALSE; /* spa_destroy() unloads wrapping keys */ } @@ -1523,6 +1549,7 @@ zfs_ioc_pool_create(zfs_cmd_t *zc) nvlist_free(props); dsl_crypto_params_free(dcp, unload_wkey && !!error); + dprintf("%s:%d: Returning with %d\n", __func__, __LINE__, error); return (error); } @@ -1533,6 +1560,7 @@ zfs_ioc_pool_destroy(zfs_cmd_t *zc) zfs_log_history(zc); error = spa_destroy(zc->zc_name); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1543,21 +1571,26 @@ zfs_ioc_pool_import(zfs_cmd_t *zc) uint64_t guid; int error; + dprintf("%s:%d: zc = 0x%p\n", __func__, __LINE__, zc); if ((error = get_nvlist(zc->zc_nvlist_conf, zc->zc_nvlist_conf_size, - zc->zc_iflags, &config)) != 0) + zc->zc_iflags, &config)) != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); + } if (zc->zc_nvlist_src_size != 0 && (error = get_nvlist(zc->zc_nvlist_src, zc->zc_nvlist_src_size, zc->zc_iflags, &props))) { nvlist_free(config); + dprintf("%s:%d: zc->zc_nvlist_src_size = %llu. Returning %d\n", + __func__, __LINE__, zc->zc_nvlist_src_size, error); return (error); } if (nvlist_lookup_uint64(config, ZPOOL_CONFIG_POOL_GUID, &guid) != 0 || - guid != zc->zc_guid) + guid != zc->zc_guid) { error = SET_ERROR(EINVAL); - else + } else error = spa_import(zc->zc_name, config, props, zc->zc_cookie); if (zc->zc_nvlist_dst != 0) { @@ -1570,6 +1603,7 @@ zfs_ioc_pool_import(zfs_cmd_t *zc) nvlist_free(config); nvlist_free(props); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1583,6 +1617,7 @@ zfs_ioc_pool_export(zfs_cmd_t *zc) zfs_log_history(zc); error = spa_export(zc->zc_name, NULL, force, hardforce); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1859,6 +1894,7 @@ zfs_ioc_vdev_add(zfs_cmd_t *zc) nvlist_free(config); } spa_close(spa, FTAG); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -1875,14 +1911,17 @@ zfs_ioc_vdev_remove(zfs_cmd_t *zc) int error; error = spa_open(zc->zc_name, &spa, FTAG); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); + } if (zc->zc_cookie != 0) { error = spa_vdev_remove_cancel(spa); } else { error = spa_vdev_remove(spa, zc->zc_guid, B_FALSE); } spa_close(spa, FTAG); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -2577,8 +2616,9 @@ zfs_set_prop_nvlist(const char *dsname, zprop_source_t source, nvlist_t *nvl, nvlist_t *attrs; attrs = fnvpair_value_nvlist(pair); if (nvlist_lookup_nvpair(attrs, ZPROP_VALUE, - &propval) != 0) + &propval) != 0) { err = SET_ERROR(EINVAL); + } } /* Validate value type */ @@ -2599,7 +2639,8 @@ zfs_set_prop_nvlist(const char *dsname, zprop_source_t source, nvlist_t *nvl, } } else if (err == 0) { if (nvpair_type(propval) == DATA_TYPE_STRING) { - if (zfs_prop_get_type(prop) != PROP_TYPE_STRING) + if (zfs_prop_get_type(prop) != + PROP_TYPE_STRING) err = SET_ERROR(EINVAL); } else if (nvpair_type(propval) == DATA_TYPE_UINT64) { const char *unused; @@ -2614,9 +2655,10 @@ zfs_set_prop_nvlist(const char *dsname, zprop_source_t source, nvlist_t *nvl, break; case PROP_TYPE_INDEX: if (zfs_prop_index_to_string(prop, - intval, &unused) != 0) + intval, &unused) != 0) { err = SET_ERROR(ZFS_ERR_BADPROP); + } break; default: cmn_err(CE_PANIC, @@ -2656,6 +2698,8 @@ zfs_set_prop_nvlist(const char *dsname, zprop_source_t source, nvlist_t *nvl, if (err != 0) { if (errlist != NULL) fnvlist_add_int32(errlist, propname, err); + dprintf("%s:%d: Setting rv = %d\n", __func__, __LINE__, + rv); rv = err; } @@ -2715,6 +2759,7 @@ zfs_set_prop_nvlist(const char *dsname, zprop_source_t source, nvlist_t *nvl, nvlist_free(genericnvl); nvlist_free(retrynvl); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, rv); return (rv); } @@ -2824,6 +2869,7 @@ zfs_ioc_set_prop(zfs_cmd_t *zc) nvlist_free(errors); nvlist_free(nvl); + dprintf("%s:%d: zfs set Returning %d\n", __func__, __LINE__, error); return (error); } @@ -3130,8 +3176,9 @@ zfs_fill_zplprops_impl(objset_t *os, uint64_t zplver, (zplver >= ZPL_VERSION_SA && !sa_ok) || (zplver < ZPL_VERSION_NORMALIZATION && (norm != ZFS_PROP_UNDEFINED || u8 != ZFS_PROP_UNDEFINED || - sense != ZFS_PROP_UNDEFINED))) + sense != ZFS_PROP_UNDEFINED))) { return (SET_ERROR(ENOTSUP)); + } /* * Put the version in the zplprops @@ -3140,8 +3187,11 @@ zfs_fill_zplprops_impl(objset_t *os, uint64_t zplver, zfs_prop_to_name(ZFS_PROP_VERSION), zplver) == 0); if (norm == ZFS_PROP_UNDEFINED && - (error = zfs_get_zplprop(os, ZFS_PROP_NORMALIZE, &norm)) != 0) + (error = zfs_get_zplprop(os, ZFS_PROP_NORMALIZE, &norm)) != 0) { + dprintf("%s:%d: Returning error %d \n", __func__, __LINE__, + error); return (error); + } VERIFY(nvlist_add_uint64(zplprops, zfs_prop_to_name(ZFS_PROP_NORMALIZE), norm) == 0); @@ -3151,14 +3201,20 @@ zfs_fill_zplprops_impl(objset_t *os, uint64_t zplver, if (norm) u8 = 1; if (u8 == ZFS_PROP_UNDEFINED && - (error = zfs_get_zplprop(os, ZFS_PROP_UTF8ONLY, &u8)) != 0) + (error = zfs_get_zplprop(os, ZFS_PROP_UTF8ONLY, &u8)) != 0) { + dprintf("%s:%d: Returning error %d \n", __func__, __LINE__, + error); return (error); + } VERIFY(nvlist_add_uint64(zplprops, zfs_prop_to_name(ZFS_PROP_UTF8ONLY), u8) == 0); if (sense == ZFS_PROP_UNDEFINED && - (error = zfs_get_zplprop(os, ZFS_PROP_CASE, &sense)) != 0) + (error = zfs_get_zplprop(os, ZFS_PROP_CASE, &sense)) != 0) { + dprintf("%s:%d: Returning error %d \n", __func__, __LINE__, + error); return (error); + } VERIFY(nvlist_add_uint64(zplprops, zfs_prop_to_name(ZFS_PROP_CASE), sense) == 0); @@ -3269,8 +3325,9 @@ zfs_ioc_create(const char *fsname, nvlist_t *innvl, nvlist_t *outnvl) break; } if (strchr(fsname, '@') || - strchr(fsname, '%')) + strchr(fsname, '%')) { return (SET_ERROR(EINVAL)); + } zct.zct_props = nvprops; @@ -3282,14 +3339,17 @@ zfs_ioc_create(const char *fsname, nvlist_t *innvl, nvlist_t *outnvl) if (nvprops == NULL) return (SET_ERROR(EINVAL)); + if (nvlist_lookup_uint64(nvprops, - zfs_prop_to_name(ZFS_PROP_VOLSIZE), &volsize) != 0) + zfs_prop_to_name(ZFS_PROP_VOLSIZE), &volsize) != 0) { return (SET_ERROR(EINVAL)); + } if ((error = nvlist_lookup_uint64(nvprops, zfs_prop_to_name(ZFS_PROP_VOLBLOCKSIZE), - &volblocksize)) != 0 && error != ENOENT) + &volblocksize)) != 0 && error != ENOENT) { return (SET_ERROR(EINVAL)); + } if (error != 0) volblocksize = zfs_prop_default_numeric( @@ -3359,6 +3419,7 @@ zfs_ioc_create(const char *fsname, nvlist_t *innvl, nvlist_t *outnvl) } } } + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); return (error); } @@ -3525,6 +3586,7 @@ zfs_ioc_log_history(const char *unused, nvlist_t *innvl, nvlist_t *outnvl) poolname = tsd_get(zfs_allow_log_key); if (poolname == NULL) return (SET_ERROR(EINVAL)); + (void) tsd_set(zfs_allow_log_key, NULL); error = spa_open(poolname, &spa, FTAG); kmem_strfree(poolname); @@ -3911,7 +3973,7 @@ zfs_ioc_destroy(zfs_cmd_t *zc) if (ost == DMU_OST_ZVOL) zvol_os_detach(zc->zc_name); #endif - + if (strchr(zc->zc_name, '@')) { err = dsl_destroy_snapshot(zc->zc_name, zc->zc_defer_destroy); } else { @@ -3951,6 +4013,7 @@ zfs_ioc_destroy(zfs_cmd_t *zc) zvol_os_attach(zc->zc_name); #endif + dprintf("%s:%d: Returning %d \n", __func__, __LINE__, err); return (err); } @@ -7271,6 +7334,8 @@ zfs_check_input_nvpairs(nvlist_t *innvl, const zfs_ioc_vec_t *vec) const zfs_ioc_key_t *nvl_keys = vec->zvec_nvl_keys; boolean_t required_keys_found = B_FALSE; + dprintf("%s:%d: innvl = 0x%p, vec = 0x%p\n", __func__, __LINE__, innvl, + vec); /* * examine each input pair */ @@ -7327,6 +7392,7 @@ zfs_check_input_nvpairs(nvlist_t *innvl, const zfs_ioc_vec_t *vec) return (SET_ERROR(ZFS_ERR_IOC_ARG_REQUIRED)); } + TraceEvent(8, "%s:%d: Returning with 0\n", __func__, __LINE__); return (0); } @@ -7337,11 +7403,16 @@ pool_status_check(const char *name, zfs_ioc_namecheck_t type, spa_t *spa; int error; + TraceEvent(5, "%s:%d: name = %s, type = %d, check = %d\n", __func__, + __LINE__, (name ? name : "NULL"), type, check); ASSERT(type == POOL_NAME || type == DATASET_NAME || type == ENTITY_NAME); - if (check & POOL_CHECK_NONE) + if (check & POOL_CHECK_NONE) { + TraceEvent(8, "%s:%d: check = %d. Returning 0\n", __func__, + __LINE__, check); return (0); + } error = spa_open(name, &spa, FTAG); if (error == 0) { @@ -7351,6 +7422,13 @@ pool_status_check(const char *name, zfs_ioc_namecheck_t type, error = SET_ERROR(EROFS); spa_close(spa, FTAG); } + + if (error) + dprintf("%s:%d: Returning with error %d\n", __func__, __LINE__, + error); + else + TraceEvent(8, "%s:%d: Returning with error %d\n", __func__, + __LINE__, error); return (error); } diff --git a/module/zfs/zil.c b/module/zfs/zil.c index 78d0711cce4e..ed97000aab2f 100644 --- a/module/zfs/zil.c +++ b/module/zfs/zil.c @@ -3346,8 +3346,11 @@ zil_suspend(const char *osname, void **cookiep) int error; error = dmu_objset_hold(osname, suspend_tag, &os); - if (error != 0) + if (error != 0) { + dprintf("%s:%d: dmu_objset_hold returned %d\n", __func__, + __LINE__, error); return (error); + } zilog = dmu_objset_zil(os); mutex_enter(&zilog->zl_lock); @@ -3369,6 +3372,7 @@ zil_suspend(const char *osname, void **cookiep) (zilog->zl_suspend > 0 || BP_IS_HOLE(&zh->zh_log))) { mutex_exit(&zilog->zl_lock); dmu_objset_rele(os, suspend_tag); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -3391,6 +3395,7 @@ zil_suspend(const char *osname, void **cookiep) zil_resume(os); else *cookiep = os; + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -3404,6 +3409,7 @@ zil_suspend(const char *osname, void **cookiep) *cookiep = os; mutex_exit(&zilog->zl_lock); + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } @@ -3653,8 +3659,11 @@ zil_reset(const char *osname, void *arg) /* EACCES means crypto key not loaded */ if ((error == EACCES) || (error == EBUSY)) return (SET_ERROR(error)); + if (error != 0) return (SET_ERROR(EEXIST)); + + TraceEvent(8, "%s:%d: Returning 0\n", __func__, __LINE__); return (0); } diff --git a/module/zfs/zio.c b/module/zfs/zio.c index e33d36dab5f9..95cdac9c0643 100644 --- a/module/zfs/zio.c +++ b/module/zfs/zio.c @@ -2223,6 +2223,8 @@ zio_wait(zio_t *zio) long timeout = MSEC_TO_TICK(zfs_deadman_ziotime_ms); int error; + TraceEvent(8, "%s:%d: zio = 0x%p\n", __func__, __LINE__, zio); + ASSERT3S(zio->io_stage, ==, ZIO_STAGE_OPEN); ASSERT3P(zio->io_executor, ==, NULL); @@ -2251,6 +2253,12 @@ zio_wait(zio_t *zio) error = zio->io_error; zio_destroy(zio); + if (error) + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, error); + else + TraceEvent(8, "%s:%d: Returning %d\n", __func__, __LINE__, + error); + return (error); } diff --git a/module/zfs/zio_inject.c b/module/zfs/zio_inject.c index feaf41dc65e3..f494db4a20ef 100644 --- a/module/zfs/zio_inject.c +++ b/module/zfs/zio_inject.c @@ -363,6 +363,8 @@ zio_handle_device_injection_impl(vdev_t *vd, zio_t *zio, int err1, int err2) inject_handler_t *handler; int ret = 0; + dprintf("%s:%d: vd = 0x%p, zio = 0x%p, err1 = %d, err2 = %d\n", + __func__, __LINE__, vd, zio, err1, err2); /* * We skip over faults in the labels unless it's during * device open (i.e. zio == NULL). @@ -371,8 +373,12 @@ zio_handle_device_injection_impl(vdev_t *vd, zio_t *zio, int err1, int err2) uint64_t offset = zio->io_offset; if (offset < VDEV_LABEL_START_SIZE || - offset >= vd->vdev_psize - VDEV_LABEL_END_SIZE) + offset >= vd->vdev_psize - VDEV_LABEL_END_SIZE) { + dprintf("%s:%d: offset = %llu, vd->vdev_psize = %llu. " + "Returning 0\n", __func__, __LINE__, + offset, vd->vdev_psize); return (0); + } } rw_enter(&inject_lock, RW_READER); @@ -447,6 +453,7 @@ zio_handle_device_injection_impl(vdev_t *vd, zio_t *zio, int err1, int err2) rw_exit(&inject_lock); + dprintf("%s:%d: Returning %d\n", __func__, __LINE__, ret); return (ret); }