scoutfs: make trace format a little nicer

The first trace format was pretty noisy.  Now the time is printed in a
gettimeofday timeval so that it can be correlated with other time
stamps.  The super block gets a counter instead of a pointer.  The pid
and cpu are printed without a lavel and we add the line number so that
it's easy to grep the source to find a trace caller.

Signed-off-by: Zach Brown <zab@versity.com>

kmod/src/super.c

@@ -128,6 +128,12 @@ static int read_supers(struct super_block *sb)
 	return 0;
 }
 
+/*
+ * Only used for tracing output, it's a convenient way to cheaply differentiate
+ * messages from different super blocks.
+ */
+static atomic64_t scoutfs_sb_ctr = ATOMIC64_INIT(0);
+
 static int scoutfs_fill_super(struct super_block *sb, void *data, int silent)
 {
 	struct scoutfs_sb_info *sbi;
@@ -158,6 +164,8 @@ static int scoutfs_fill_super(struct super_block *sb, void *data, int silent)
 	init_waitqueue_head(&sbi->trans_write_wq);
 	INIT_LIST_HEAD(&sbi->roster_head);
 
+	sbi->ctr = atomic64_inc_return(&scoutfs_sb_ctr);
+
 	/* XXX can have multiple mounts of a  device, need mount id */
 	sbi->kset = kset_create_and_add(sb->s_id, NULL, &scoutfs_kset->kobj);
 	if (!sbi->kset)

kmod/src/super.h

@@ -14,6 +14,8 @@ struct wrlock_context;
 struct scoutfs_sb_info {
 	struct super_block *sb;
 
+	u64 ctr;
+
 	struct scoutfs_super_block super;
 
 	spinlock_t next_ino_lock;

kmod/src/trace.h

@@ -97,18 +97,22 @@ static inline void only_check_format(const char *fmt, ...)
  */
 #define scoutfs_trace(sb, fmt, ...) 					\
 do {									\
+	struct scoutfs_sb_info *__sbi = SCOUTFS_SB(sb);			\
 	static char __scoutfs_trace_section __fmt[] = 			\
-		"ns %llu sb %llx pid %llu cpu %llu "fmt; 		\
+		"[%llu.%llu] %llu %llu %llu " __stringify(__LINE__) ": "\
+		fmt;							\
+	struct timeval __tv;						\
 									\
 	BUILD_BUG_ON(fmt[sizeof(fmt) - 2] == '\n');			\
 									\
 	/* check the caller's format before we prepend things to it */	\
 	only_check_format(fmt, CAST_ARGS_U64(__VA_ARGS__));		\
 									\
-	__trace_write(__fmt, 						\
-		      CAST_ARGS_U64(sched_clock(), (long)(sb),		\
-				    current->pid, get_cpu(),		\
-				    __VA_ARGS__));			\
+	do_gettimeofday(&__tv);						\
+									\
+	__trace_write(__fmt, CAST_ARGS_U64(__tv.tv_sec, __tv.tv_usec,	\
+		      __sbi->ctr, current->pid, get_cpu(),		\
+		      __VA_ARGS__));					\
 	put_cpu();							\
 } while (0)