Commit 3e158bd5 authored by Konrad Sztyber's avatar Konrad Sztyber Committed by Jim Harris
Browse files

lib/trace: record string arguments as (const char *) 



Now that `spdk_trace_record` receives variadic arguments, we no longer
have to pass strings as uint64_t, but can pass them directly as
pointers.  That also means that the recorded strings can be longer than
8B (up to 40B).

This patch changes the blobfs code to pass the filenames as strings and
gets rid of the code that converted them to uint64_t.

Additionally, the maximum length of string arguments printed by
`app/trace/trace` has been extended to 16 and they're also padded to 16
characters, to better align with other argument types.

Signed-off-by: default avatarKonrad Sztyber <konrad.sztyber@intel.com>
Change-Id: Ibe94452bf1b27eba2b15ca8608d0c3b55c2db360
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/7957


Tested-by: default avatarSPDK CI Jenkins <sys_sgci@intel.com>
Community-CI: Mellanox Build Bot
Reviewed-by: default avatarZiye Yang <ziye.yang@intel.com>
Reviewed-by: default avatarJim Harris <james.r.harris@intel.com>
Reviewed-by: default avatarAleksey Marchuk <alexeymar@mellanox.com>
parent f301d156

app/trace/trace.cpp

+5 −5
Original line number Diff line number Diff line
@@ -120,10 +120,9 @@ print_uint64(const char *arg_string, uint64_t arg) 
}



static void

print_string(const char *arg_string, uint64_t arg)

print_string(const char *arg_string, const char *arg)

{

	char *str = (char *)&arg;

	printf("%-7.7s%.8s ", format_argname(arg_string), str);

	printf("%-7.7s%-16.16s ", format_argname(arg_string), arg);

}



static void
@@ -158,16 +157,17 @@ print_arg(uint8_t arg_type, const char *arg_string, const void *arg) 
		return;

	}



	memcpy(&value, arg, sizeof(value));

	switch (arg_type) {

	case SPDK_TRACE_ARG_TYPE_PTR:

		memcpy(&value, arg, sizeof(value));

		print_ptr(arg_string, value);

		break;

	case SPDK_TRACE_ARG_TYPE_INT:

		memcpy(&value, arg, sizeof(value));

		print_uint64(arg_string, value);

		break;

	case SPDK_TRACE_ARG_TYPE_STR:

		print_string(arg_string, value);

		print_string(arg_string, (const char *)arg);

		break;

	}

}

lib/blobfs/blobfs.c

+40 −56
Original line number Diff line number Diff line
@@ -74,36 +74,40 @@ static pthread_mutex_t g_cache_init_lock = PTHREAD_MUTEX_INITIALIZER; 


SPDK_TRACE_REGISTER_FN(blobfs_trace, "blobfs", TRACE_GROUP_BLOBFS)

{

	spdk_trace_register_description("BLOBFS_XATTR_START",

					TRACE_BLOBFS_XATTR_START,

	struct spdk_trace_tpoint_opts opts[] = {

		{

			"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,

			{{ "file", SPDK_TRACE_ARG_TYPE_STR, 40 }},

		},

		{

			"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,

			{{ "file", SPDK_TRACE_ARG_TYPE_STR, 40 }},

		},

		{

			"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,

			{{ "file", SPDK_TRACE_ARG_TYPE_STR, 40 }},

		},

		{

			"BLOBFS_CLOSE", TRACE_BLOBFS_CLOSE,

			OWNER_NONE, OBJECT_NONE, 0,

					SPDK_TRACE_ARG_TYPE_STR,

					"file");

	spdk_trace_register_description("BLOBFS_DELETE_START",

					TRACE_BLOBFS_DELETE_START,

			{{ "file", SPDK_TRACE_ARG_TYPE_STR, 40 }},

		},

		{

			"BLOBFS_DELETE_START", TRACE_BLOBFS_DELETE_START,

			OWNER_NONE, OBJECT_NONE, 0,

					SPDK_TRACE_ARG_TYPE_STR,

					"file");

	spdk_trace_register_description("BLOBFS_DELETE_DONE",

					TRACE_BLOBFS_DELETE_DONE,

			{{ "file", SPDK_TRACE_ARG_TYPE_STR, 40 }},

		},

		{

			"BLOBFS_DELETE_DONE", TRACE_BLOBFS_DELETE_DONE,

			OWNER_NONE, OBJECT_NONE, 0,

					SPDK_TRACE_ARG_TYPE_STR,

					"file");

			{{ "file", SPDK_TRACE_ARG_TYPE_STR, 40 }},

		}

	};



	spdk_trace_register_description_ext(opts, SPDK_COUNTOF(opts));

}



void
@@ -119,7 +123,6 @@ 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;
@@ -706,14 +709,6 @@ 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)

{
@@ -761,7 +756,6 @@ 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;
@@ -1120,7 +1114,6 @@ spdk_fs_create_file_async(struct spdk_filesystem *fs, const char *name, 
		cb_fn(cb_arg, -ENOMEM);

		return;

	}

	_file_build_trace_arg_name(file);

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

}
@@ -1184,7 +1177,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);

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

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

		free_fs_request(req);

	}
@@ -1363,7 +1356,6 @@ _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);

}
@@ -1524,21 +1516,13 @@ spdk_fs_delete_file_async(struct spdk_filesystem *fs, const char *name, 
	spdk_bs_delete_blob(fs->bs, blobid, blob_delete_cb, req);

}



static uint64_t

fs_name_to_uint64(const char *name)

{

	uint64_t result = 0;

	memcpy(&result, name, spdk_min(sizeof(result), strlen(name)));

	return result;

}



static void

__fs_delete_file_done(void *arg, int fserrno)

{

	struct spdk_fs_request *req = arg;

	struct spdk_fs_cb_args *args = &req->args;



	spdk_trace_record(TRACE_BLOBFS_DELETE_DONE, 0, 0, 0, fs_name_to_uint64(args->op.delete.name));

	spdk_trace_record(TRACE_BLOBFS_DELETE_DONE, 0, 0, 0, args->op.delete.name);

	__wake_caller(args, fserrno);

}
@@ -1548,7 +1532,7 @@ __fs_delete_file(void *arg) 
	struct spdk_fs_request *req = arg;

	struct spdk_fs_cb_args *args = &req->args;



	spdk_trace_record(TRACE_BLOBFS_DELETE_START, 0, 0, 0, fs_name_to_uint64(args->op.delete.name));

	spdk_trace_record(TRACE_BLOBFS_DELETE_START, 0, 0, 0, args->op.delete.name);

	spdk_fs_delete_file_async(args->fs, args->op.delete.name, __fs_delete_file_done, req);

}
@@ -2221,7 +2205,7 @@ __file_cache_finish_sync(void *ctx, int bserrno) 
	file->length_xattr = sync_args->op.sync.length;

	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);

			  0, file->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);
@@ -2254,7 +2238,7 @@ __check_sync_reqs(struct spdk_file *file) 


		pthread_spin_unlock(&file->lock);

		spdk_trace_record(TRACE_BLOBFS_XATTR_START, 0, file->length_flushed,

				  0, file->trace_arg_name);

				  0, file->name);

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

	} else {

		pthread_spin_unlock(&file->lock);
@@ -2832,7 +2816,7 @@ __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);

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



	if (file->is_deleted) {

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

lib/trace/trace.c

+17 −4
Original line number Diff line number Diff line
@@ -52,8 +52,9 @@ _spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id, uint32_ 
	struct spdk_trace_history *lcore_history;

	struct spdk_trace_entry *next_entry;

	struct spdk_trace_tpoint *tpoint;

	const char *strval;

	unsigned lcore, i, offset;

	uint64_t value, next_circular_entry;

	uint64_t intval, next_circular_entry;

	va_list vl;



	lcore = spdk_env_get_current_core();
@@ -90,9 +91,21 @@ _spdk_trace_record(uint64_t tsc, uint16_t tpoint_id, uint16_t poller_id, uint32_ 


	va_start(vl, num_args);

	for (i = 0, offset = 0; i < tpoint->num_args; ++i) {

		/* All values are currently passed as uint64_t */

		value = va_arg(vl, uint64_t);

		memcpy(&next_entry->args[offset], &value, sizeof(value));

		switch (tpoint->args[i].type) {

		case SPDK_TRACE_ARG_TYPE_STR:

			strval = va_arg(vl, const char *);

			snprintf(&next_entry->args[offset], tpoint->args[i].size, "%s", strval);

			break;

		case SPDK_TRACE_ARG_TYPE_INT:

		case SPDK_TRACE_ARG_TYPE_PTR:

			intval = va_arg(vl, uint64_t);

			memcpy(&next_entry->args[offset], &intval, sizeof(intval));

			break;

		default:

			assert(0 && "Invalid trace argument type");

			break;

		}



		offset += tpoint->args[i].size;

	}

	va_end(vl);

lib/trace/trace_flags.c

+5 −2
Original line number Diff line number Diff line
@@ -310,10 +310,13 @@ trace_register_description(const struct spdk_trace_tpoint_opts *opts) 
		switch (opts->args[i].type) {

		case SPDK_TRACE_ARG_TYPE_INT:

		case SPDK_TRACE_ARG_TYPE_PTR:

		case SPDK_TRACE_ARG_TYPE_STR:

			/* For now all trace types need to be passed as uint64_t */

			/* The integers and pointers have to be exactly 64b long */

			assert(opts->args[i].size == sizeof(uint64_t));

			break;

		case SPDK_TRACE_ARG_TYPE_STR:

			/* Strings need to have at least one byte for the NULL terminator */

			assert(opts->args[i].size > 0);

			break;

		default:

			assert(0 && "invalid trace argument type");

			break;