[Devel] [PATCH VZ9 17/20] fuse: pcs: split trace_printk
Alexey Kuznetsov
kuznet at virtuozzo.com
Fri Oct 6 13:44:03 MSK 2023
trace_printk() is a function which is not desired in release kernels,
if is referenced from a module, even if it is not actually used, it allocates
lots of memory and scares people with some messages.
What can we do?
1. Surround it with ifdef turned off in release kernels
No. We need this at customer's environments to investigate actual problems,
modules cannot be replaced with debugging when they are in use.
2. Just delete it.
Instead we could use systemtap to attach to running module to get desired traces.
This facility is used frequently in any case. Contra: systemtap puts
heavy overhead, it is not easy to install, frequently customers are heavily
firewalled and do not allow debugging software to pollute their systems.
One day, when bpftrace becomes mature it could be an option. Right now
it is still useless.
3. Convert them to userspace logging FUSE_KTRACE at higher loglevel.
Too expensive. We do not need this garbage in user space logs and it is not easy,
userpace logging requires context pointer which is diffficult or impossible to fetch.
So, the third variant is suggested. It is some compromise, we preserve
debugging in code, but split actual uses of trace_printk to separate module,
which can be loaded when we need tracing. It is more expensive, includes
an indirect call and does not allow inline calls, but yet it still looks better
than any other way. Also, a few TRACE which have analogs in userspace were
missed, convert them to FUSE_KTRACE now.
Affects: #PSBM-146513
Signed-off-by: Alexey Kuznetsov <kuznet at acronis.com>
---
fs/fuse/Makefile | 3 ++-
fs/fuse/kio/pcs/fuse_kio_pcs_trace.c | 35 +++++++++++++++++++++++++++++++++++
fs/fuse/kio/pcs/log.h | 26 ++++++++++++++++++++++++--
fs/fuse/kio/pcs/pcs_cs.c | 10 +++++-----
fs/fuse/kio/pcs/pcs_fuse_kdirect.c | 3 +++
fs/fuse/kio/pcs/pcs_map.c | 2 +-
fs/fuse/kio/pcs/pcs_rpc.c | 2 +-
fs/fuse/kio/pcs/pcs_sock_io.c | 6 ++++--
8 files changed, 75 insertions(+), 12 deletions(-)
create mode 100644 fs/fuse/kio/pcs/fuse_kio_pcs_trace.c
diff --git a/fs/fuse/Makefile b/fs/fuse/Makefile
index afed004..740c805 100644
--- a/fs/fuse/Makefile
+++ b/fs/fuse/Makefile
@@ -16,7 +16,7 @@ fuse_kio_noop-objs := kio/kio_noop.o
obj-$(CONFIG_FUSE_KIO_NULLIO) += fuse_kio_nullio.o
fuse_kio_nullio-objs := kio/kio_nullio.o
-obj-$(CONFIG_FUSE_KIO_PCS) += fuse_kio_pcs.o
+obj-$(CONFIG_FUSE_KIO_PCS) += fuse_kio_pcs.o fuse_kio_pcs_trace.o
fuse_kio_pcs-objs := kio/pcs/pcs_fuse_kdirect.o \
kio/pcs/pcs_sock_io.o \
kio/pcs/pcs_rpc.o \
@@ -34,5 +34,6 @@ fuse_kio_pcs-objs := kio/pcs/pcs_fuse_kdirect.o \
kio/pcs/pcs_rdma_conn.o \
kio/pcs/pcs_net_addr.o \
kio/pcs/pcs_cs_accel.o
+fuse_kio_pcs_trace-objs := kio/pcs/fuse_kio_pcs_trace.o
virtiofs-y := virtio_fs.o
diff --git a/fs/fuse/kio/pcs/fuse_kio_pcs_trace.c b/fs/fuse/kio/pcs/fuse_kio_pcs_trace.c
new file mode 100644
index 0000000..d36ff37
--- /dev/null
+++ b/fs/fuse/kio/pcs/fuse_kio_pcs_trace.c
@@ -0,0 +1,35 @@
+#include <linux/types.h>
+#include <linux/module.h>
+#include <linux/kernel.h>
+#include <linux/trace.h>
+
+#include "pcs_types.h"
+#include "log.h"
+
+static void _fuse_printk_plugin(unsigned long ip, const char *fmt, ...)
+{
+ va_list args;
+
+ va_start(args, fmt);
+ __ftrace_vbprintk(ip, fmt, args);
+ va_end(args);
+}
+
+static int __init kpcs_printk_mod_init(void)
+{
+ trace_printk_init_buffers();
+ rcu_assign_pointer(fuse_printk_plugin, _fuse_printk_plugin);
+ return 0;
+}
+
+static void __exit kpcs_printk_mod_exit(void)
+{
+ rcu_assign_pointer(fuse_printk_plugin, NULL);
+ synchronize_rcu();
+}
+
+module_init(kpcs_printk_mod_init);
+module_exit(kpcs_printk_mod_exit);
+
+MODULE_LICENSE("GPL v2");
+MODULE_AUTHOR("Virtuozzo <devel at openvz.org>");
diff --git a/fs/fuse/kio/pcs/log.h b/fs/fuse/kio/pcs/log.h
index 6a2ceef..57a0ad0 100644
--- a/fs/fuse/kio/pcs/log.h
+++ b/fs/fuse/kio/pcs/log.h
@@ -31,6 +31,28 @@
extern unsigned int pcs_loglevel;
extern unsigned int debugfs_tracing;
-#define TRACE(fmt, args...) if (unlikely(debugfs_tracing && pcs_loglevel >= LOG_TRACE)) trace_printk("%d: " fmt "\n", __LINE__, ## args)
-#define DTRACE(fmt, args...) if (unlikely(debugfs_tracing && pcs_loglevel >= LOG_DTRACE)) trace_printk("%d: " fmt "\n", __LINE__, ## args)
+extern void (*fuse_printk_plugin)(unsigned long, const char *fmt, ...);
+
+#define fuse_kio_trace_printk(fmt, ...) \
+do { \
+ char _______STR[] = __stringify((__VA_ARGS__)); \
+ if (sizeof(_______STR) > 3) \
+ __fuse_kio_do_trace_printk(fmt, ##__VA_ARGS__); \
+ else \
+ __trace_puts(_THIS_IP_, fmt, strlen(fmt)); \
+} while (0)
+
+#define __fuse_kio_do_trace_printk(fmt, ...) \
+do { \
+ void (*__plugin)(unsigned long, const char *, ...); \
+ __trace_printk_check_format(fmt, ##__VA_ARGS__); \
+ rcu_read_lock(); \
+ __plugin = rcu_dereference(fuse_printk_plugin); \
+ if (__plugin) (*__plugin)(_THIS_IP_, fmt, ##__VA_ARGS__); \
+ rcu_read_unlock(); \
+} while (0)
+
+
+#define TRACE(fmt, ...) if (unlikely(debugfs_tracing && pcs_loglevel >= LOG_TRACE)) fuse_kio_trace_printk(__stringify(__LINE__) ": " fmt, ##__VA_ARGS__)
+#define DTRACE(fmt, ...) if (unlikely(debugfs_tracing && pcs_loglevel >= LOG_DTRACE)) fuse_kio_trace_printk(__stringify(__LINE__) ": " fmt, ##__VA_ARGS__)
#endif /* __PCSLOG_H__ */
diff --git a/fs/fuse/kio/pcs/pcs_cs.c b/fs/fuse/kio/pcs/pcs_cs.c
index 20840f8..6cc97aa 100644
--- a/fs/fuse/kio/pcs/pcs_cs.c
+++ b/fs/fuse/kio/pcs/pcs_cs.c
@@ -430,7 +430,7 @@ static void cs_get_read_response_iter(struct pcs_msg *msg, int offset, struct io
msg->_inline_kv.iov_len = sizeof(struct pcs_cs_iohdr);
iov_iter_kvec(it, direction, &msg->_inline_kv, 1, sizeof(struct pcs_cs_iohdr));
iov_iter_advance(it, offset);
- TRACE("return msg:%p->size:%d off:%d it_len:%ld\n\n", msg, msg->size, offset, iov_iter_count(it));
+ TRACE("return msg:%p->size:%d off:%d it_len:%ld\n", msg, msg->size, offset, iov_iter_count(it));
return;
} else {
struct pcs_msg *req = msg->private;
@@ -448,7 +448,7 @@ static void cs_get_read_response_iter(struct pcs_msg *msg, int offset, struct io
iov_iter_truncate(it, msg->size - sizeof(struct pcs_cs_iohdr));
iov_iter_advance(it, offset);
- TRACE("return msg:%p->size:%d off:%d it_len:%ld\n\n", msg, msg->size, offset, iov_iter_count(it));
+ TRACE("return msg:%p->size:%d off:%d it_len:%ld\n", msg, msg->size, offset, iov_iter_count(it));
return;
} else
BUG();
@@ -551,7 +551,7 @@ static void cs_get_data(struct pcs_msg *msg, int offset, struct iov_iter *it, un
ireq->iochunk.hbuf_kv.iov_len = sizeof(struct pcs_cs_iohdr);
iov_iter_kvec(it, direction, &ireq->iochunk.hbuf_kv, 1, sizeof(struct pcs_cs_iohdr));
iov_iter_advance(it, offset);
- TRACE("return msg:%p->size:%d off:%d it_len:%ld\n\n", msg, msg->size, offset, iov_iter_count(it));
+ TRACE("return msg:%p->size:%d off:%d it_len:%ld\n", msg, msg->size, offset, iov_iter_count(it));
return;
} else {
@@ -566,7 +566,7 @@ static void cs_get_data(struct pcs_msg *msg, int offset, struct iov_iter *it, un
iov_iter_truncate(it, ireq->iochunk.size);
iov_iter_advance(it, offset);
- TRACE("return msg:%p->size:%d off:%d it_len:%ld\n\n", msg, msg->size, offset, iov_iter_count(it));
+ TRACE("return msg:%p->size:%d off:%d it_len:%ld\n", msg, msg->size, offset, iov_iter_count(it));
return;
} else
BUG();
@@ -1218,7 +1218,7 @@ unsigned int cs_get_avg_in_flight(struct pcs_cs *cs)
}
if (cs->cwnd > PCS_CS_INIT_CWND) {
unsigned int cwnd = PCS_CS_INIT_CWND;
- TRACE("Congestion window on CS#" NODE_FMT " was not used, shrink %u -> %u", NODE_ARGS(cs->id),
+ FUSE_KTRACE(cc_from_csset(cs->css)->fc, "Congestion window on CS#" NODE_FMT " was not used, shrink %u -> %u", NODE_ARGS(cs->id),
cs->cwnd, cwnd);
if (cs->cwnd > cs->ssthresh)
cs->ssthresh = cs->cwnd;
diff --git a/fs/fuse/kio/pcs/pcs_fuse_kdirect.c b/fs/fuse/kio/pcs/pcs_fuse_kdirect.c
index 39a6aaf..566dcb5 100644
--- a/fs/fuse/kio/pcs/pcs_fuse_kdirect.c
+++ b/fs/fuse/kio/pcs/pcs_fuse_kdirect.c
@@ -71,6 +71,9 @@
module_param(rdmaio_queue_depth, uint, 0644);
MODULE_PARM_DESC(rdmaio_queue_depth, "RDMA queue depth");
+void (*fuse_printk_plugin)(unsigned long, const char *, ...);
+EXPORT_SYMBOL(fuse_printk_plugin);
+
static LIST_HEAD(pcs_client_list);
spinlock_t pcs_clients_lock;
diff --git a/fs/fuse/kio/pcs/pcs_map.c b/fs/fuse/kio/pcs/pcs_map.c
index f0520ba..ae13557 100644
--- a/fs/fuse/kio/pcs/pcs_map.c
+++ b/fs/fuse/kio/pcs/pcs_map.c
@@ -655,7 +655,7 @@ static int all_blacklisted(struct pcs_cs_list * csl)
if (test_bit(i, &csl->blacklist)) {
if (jiffies < READ_ONCE(csl->blacklist_expires))
continue;
- TRACE("expire replication blacklist");
+ FUSE_KTRACE(cc_from_csset(csl->cs[i].cslink.cs->css)->fc, "expire replication blacklist");
clear_bit(i, &csl->blacklist);
}
if (!test_bit(CS_SF_BLACKLISTED, &csl->cs[i].cslink.cs->state))
diff --git a/fs/fuse/kio/pcs/pcs_rpc.c b/fs/fuse/kio/pcs/pcs_rpc.c
index 8631f8e..4fbb25d 100644
--- a/fs/fuse/kio/pcs/pcs_rpc.c
+++ b/fs/fuse/kio/pcs/pcs_rpc.c
@@ -823,7 +823,7 @@ static void calendar_work(struct work_struct *w)
count++;
}
if (count)
- trace_printk("%s %d messages to "PEER_FMT" destroyed\n", __FUNCTION__,
+ FUSE_KTRACE(cc->fc, "%s %d messages to "PEER_FMT" destroyed\n", __FUNCTION__,
count, PEER_ARGS(ep));
for (i=0; i < RPC_MAX_CALENDAR-1; i++) {
diff --git a/fs/fuse/kio/pcs/pcs_sock_io.c b/fs/fuse/kio/pcs/pcs_sock_io.c
index 07b17ed..fc76e32 100644
--- a/fs/fuse/kio/pcs/pcs_sock_io.c
+++ b/fs/fuse/kio/pcs/pcs_sock_io.c
@@ -16,7 +16,9 @@
#include "pcs_types.h"
#include "pcs_sock_io.h"
#include "pcs_rpc.h"
+#include "pcs_cluster.h"
#include "log.h"
+#include "fuse_ktrace.h"
void pcs_msg_sent(struct pcs_msg * msg)
@@ -748,7 +750,7 @@ static void pcs_sock_throttle(struct pcs_netio *netio)
test_bit(PCS_IOCONN_BF_DEAD, &sio->io_flags))
return;
- DTRACE("Throttle on socket %p rpc=%p", sio, sio->netio.parent);
+ FUSE_KDTRACE(cc_from_rpc(sio->netio.parent->eng)->fc, "Throttle on socket %p rpc=%p", sio, sio->netio.parent);
sio->flags |= PCS_SOCK_F_THROTTLE;
}
@@ -760,7 +762,7 @@ static void pcs_sock_unthrottle(struct pcs_netio *netio)
test_bit(PCS_IOCONN_BF_DEAD, &sio->io_flags))
return;
- DTRACE("Unthrottle on socket %p rpc=%p", sio, sio->netio.parent);
+ FUSE_KDTRACE(cc_from_rpc(sio->netio.parent->eng)->fc, "Unthrottle on socket %p rpc=%p", sio, sio->netio.parent);
sio->flags &= ~PCS_SOCK_F_THROTTLE;
if ((sio->flags & PCS_SOCK_F_EOF))
return;
--
1.8.3.1
More information about the Devel
mailing list