Commit f71fed21 authored by Jim Harris's avatar Jim Harris
Browse files

blobfs: add trace events 



For now, just do events for open, close and start/end
for writing the length xattr.  These will be useful for
debugging the intermittent RocksDB failures.

Note these events may only be recorded on the polling
SPDK thread.  SPDK events cannot be recorded on
non-SPDK threads (i.e. RocksDB user or background threads).

Signed-off-by: default avatarJim Harris <james.r.harris@intel.com>
Change-Id: I72fb302db23b399f583f56194c237340587f3027

Reviewed-on: https://review.gerrithub.io/c/spdk/spdk/+/452262


Tested-by: default avatarSPDK CI Jenkins <sys_sgci@intel.com>
Reviewed-by: default avatarChangpeng Liu <changpeng.liu@intel.com>
Reviewed-by: default avatarZiye Yang <ziye.yang@intel.com>
Reviewed-by: default avatarDarek Stojaczyk <dariusz.stojaczyk@intel.com>
parent 37887b60

lib/blobfs/blobfs.c

+50 −0
Original line number Diff line number Diff line
@@ -43,6 +43,7 @@ 
#include "spdk/env.h"

#include "spdk/util.h"

#include "spdk_internal/log.h"

#include "spdk/trace.h"



#define BLOBFS_TRACE(file, str, args...) \

	SPDK_DEBUGLOG(SPDK_LOG_BLOBFS, "file=%s " str, file->name, ##args)
@@ -60,6 +61,36 @@ static int g_fs_count = 0; 
static pthread_mutex_t g_cache_init_lock = PTHREAD_MUTEX_INITIALIZER;

static pthread_spinlock_t g_caches_lock;



#define TRACE_GROUP_BLOBFS	0x7

#define TRACE_BLOBFS_XATTR_START	SPDK_TPOINT_ID(TRACE_GROUP_BLOBFS, 0x0)

#define TRACE_BLOBFS_XATTR_END		SPDK_TPOINT_ID(TRACE_GROUP_BLOBFS, 0x1)

#define TRACE_BLOBFS_OPEN		SPDK_TPOINT_ID(TRACE_GROUP_BLOBFS, 0x2)

#define TRACE_BLOBFS_CLOSE		SPDK_TPOINT_ID(TRACE_GROUP_BLOBFS, 0x3)



SPDK_TRACE_REGISTER_FN(blobfs_trace, "blobfs", TRACE_GROUP_BLOBFS)

{

	spdk_trace_register_description("BLOBFS_XATTR_START", "",

					TRACE_BLOBFS_XATTR_START,

					OWNER_NONE, OBJECT_NONE, 0,

					SPDK_TRACE_ARG_TYPE_STR,

					"file:    ");

	spdk_trace_register_description("BLOBFS_XATTR_END", "",

					TRACE_BLOBFS_XATTR_END,

					OWNER_NONE, OBJECT_NONE, 0,

					SPDK_TRACE_ARG_TYPE_STR,

					"file:    ");

	spdk_trace_register_description("BLOBFS_OPEN", "",

					TRACE_BLOBFS_OPEN,

					OWNER_NONE, OBJECT_NONE, 0,

					SPDK_TRACE_ARG_TYPE_STR,

					"file:    ");

	spdk_trace_register_description("BLOBFS_CLOSE", "",

					TRACE_BLOBFS_CLOSE,

					OWNER_NONE, OBJECT_NONE, 0,

					SPDK_TRACE_ARG_TYPE_STR,

					"file:    ");

}



void

spdk_cache_buffer_free(struct cache_buffer *cache_buffer)

{
@@ -73,6 +104,7 @@ struct spdk_file { 
	struct spdk_filesystem	*fs;

	struct spdk_blob	*blob;

	char			*name;

	uint64_t		trace_arg_name;

	uint64_t		length;

	bool                    is_deleted;

	bool			open_for_writing;
@@ -618,6 +650,14 @@ fs_load_done(void *ctx, int bserrno) 


}



static void

_file_build_trace_arg_name(struct spdk_file *f)

{

	f->trace_arg_name = 0;

	memcpy(&f->trace_arg_name, f->name,

	       spdk_min(sizeof(f->trace_arg_name), strlen(f->name)));

}



static void

iter_cb(void *ctx, struct spdk_blob *blob, int rc)

{
@@ -664,6 +704,7 @@ iter_cb(void *ctx, struct spdk_blob *blob, int rc) 
		}



		f->name = strdup(name);

		_file_build_trace_arg_name(f);

		f->blobid = spdk_blob_get_id(blob);

		f->length = *length;

		f->length_flushed = *length;
@@ -1016,6 +1057,7 @@ spdk_fs_create_file_async(struct spdk_filesystem *fs, const char *name, 
	args->arg = cb_arg;



	file->name = strdup(name);

	_file_build_trace_arg_name(file);

	spdk_bs_create_blob(fs->bs, fs_create_blob_create_cb, args);

}
@@ -1079,6 +1121,7 @@ fs_open_blob_done(void *ctx, struct spdk_blob *blob, int bserrno) 
		req = TAILQ_FIRST(&f->open_requests);

		args = &req->args;

		TAILQ_REMOVE(&f->open_requests, req, args.op.open.tailq);

		spdk_trace_record(TRACE_BLOBFS_OPEN, 0, 0, 0, f->trace_arg_name);

		args->fn.file_op_with_handle(args->arg, f, bserrno);

		free_fs_request(req);

	}
@@ -1255,6 +1298,7 @@ __spdk_fs_md_rename_file(struct spdk_fs_request *req) 


	free(f->name);

	f->name = strdup(args->op.rename.new_name);

	_file_build_trace_arg_name(f);

	args->file = f;

	spdk_bs_open_blob(args->fs->bs, f->blobid, fs_rename_blob_open_cb, req);

}
@@ -1956,6 +2000,8 @@ __file_cache_finish_sync(void *ctx, int bserrno) 
	sync_req = TAILQ_FIRST(&file->sync_requests);

	sync_args = &sync_req->args;

	assert(sync_args->op.sync.offset <= file->length_flushed);

	spdk_trace_record(TRACE_BLOBFS_XATTR_END, 0, sync_args->op.sync.offset,

			  0, file->trace_arg_name);

	BLOBFS_TRACE(file, "sync done offset=%jx\n", sync_args->op.sync.offset);

	TAILQ_REMOVE(&file->sync_requests, sync_req, args.op.sync.tailq);

	pthread_spin_unlock(&file->lock);
@@ -1988,6 +2034,8 @@ __check_sync_reqs(struct spdk_file *file) 
				    sizeof(file->length_flushed));



		pthread_spin_unlock(&file->lock);

		spdk_trace_record(TRACE_BLOBFS_XATTR_START, 0, file->length_flushed,

				  0, file->trace_arg_name);

		spdk_blob_sync_md(file->blob, __file_cache_finish_sync, file);

	} else {

		pthread_spin_unlock(&file->lock);
@@ -2545,6 +2593,8 @@ __file_close_async_done(void *ctx, int bserrno) 
	struct spdk_fs_cb_args *args = &req->args;

	struct spdk_file *file = args->file;



	spdk_trace_record(TRACE_BLOBFS_CLOSE, 0, 0, 0, file->trace_arg_name);



	if (file->is_deleted) {

		spdk_fs_delete_file_async(file->fs, file->name, blob_delete_cb, ctx);

		return;

test/unit/lib/blobfs/blobfs_async_ut/blobfs_async_ut.c

+8 −0
Original line number Diff line number Diff line
@@ -49,6 +49,14 @@ 
struct spdk_filesystem *g_fs;

struct spdk_file *g_file;

int g_fserrno;

struct spdk_trace_histories *g_trace_histories;

DEFINE_STUB_V(spdk_trace_add_register_fn, (struct spdk_trace_register_fn *reg_fn));

DEFINE_STUB_V(spdk_trace_register_description, (const char *name, const char *short_name,

		uint16_t tpoint_id, uint8_t owner_type,

		uint8_t object_type, uint8_t new_object,

		uint8_t arg1_is_ptr, const char *arg1_name));

DEFINE_STUB_V(_spdk_trace_record, (uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id,

				   uint32_t size, uint64_t object_id, uint64_t arg1));



/* Return NULL to test hardcoded defaults. */

struct spdk_conf_section *

test/unit/lib/blobfs/blobfs_sync_ut/blobfs_sync_ut.c

+8 −0
Original line number Diff line number Diff line
@@ -50,6 +50,14 @@ struct spdk_filesystem *g_fs; 
struct spdk_file *g_file;

int g_fserrno;

struct spdk_thread *g_dispatch_thread = NULL;

struct spdk_trace_histories *g_trace_histories;

DEFINE_STUB_V(spdk_trace_add_register_fn, (struct spdk_trace_register_fn *reg_fn));

DEFINE_STUB_V(spdk_trace_register_description, (const char *name, const char *short_name,

		uint16_t tpoint_id, uint8_t owner_type,

		uint8_t object_type, uint8_t new_object,

		uint8_t arg1_is_ptr, const char *arg1_name));

DEFINE_STUB_V(_spdk_trace_record, (uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id,

				   uint32_t size, uint64_t object_id, uint64_t arg1));



/* Return NULL to test hardcoded defaults. */

struct spdk_conf_section *