[Devel] [PATCH RHEL9 COMMIT] fuse: pcs: split trace_printk
Konstantin Khorenko
khorenko at virtuozzo.com
Wed Nov 1 22:52:16 MSK 2023
The commit is pushed to "branch-rh9-5.14.0-284.25.1.vz9.30.x-ovz" and will appear at https://src.openvz.org/scm/ovz/vzkernel.git
after rh9-5.14.0-284.25.1.vz9.30.8
------>
commit 5e3029fd1e9da56b159d9b2c80bc6522418b3806
Author: Alexey Kuznetsov <kuznet at virtuozzo.com>
Date: Fri Oct 6 18:44:03 2023 +0800
fuse: pcs: split trace_printk
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 fourth 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.
https://virtuozzo.atlassian.net/browse/PSBM-146513
Signed-off-by: Alexey Kuznetsov <kuznet at acronis.com>
Feature: vStorage
---
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(-)
diff --git a/fs/fuse/Makefile b/fs/fuse/Makefile
index afed0047b858..740c805adc2a 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 000000000000..d36ff37ce3c5
--- /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 6a2ceef2d0cf..57a0ad09dd18 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 20840f8d4295..6cc97aa3f9d0 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 39a6aaf49ab7..566dcb5f2f4c 100644
--- a/fs/fuse/kio/pcs/pcs_fuse_kdirect.c
+++ b/fs/fuse/kio/pcs/pcs_fuse_kdirect.c
@@ -71,6 +71,9 @@ unsigned int rdmaio_queue_depth = 8;
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 f0520bae8699..ae135573d806 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 8f545f952e1e..3aca05fd6c20 100644
--- a/fs/fuse/kio/pcs/pcs_rpc.c
+++ b/fs/fuse/kio/pcs/pcs_rpc.c
@@ -824,7 +824,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 07b17ed5e848..fc76e326bef5 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;
More information about the Devel
mailing list