@@ -54,6 +54,14 @@ config ANDROID_BINDER_IPC_SELFTEST
exhaustively with combinations of various buffer sizes and
alignments.
+config BINDER_TRANSACTION_LATENCY_TRACKING
+ tristate "Android Binder transaction tracking"
+ help
+ Used for track abnormal binder transaction which is over threshold,
+ when the transaction is done or be free, this transaction would be
+ checked whether it executed overtime.
+ If yes, printing out the detailed info.
+
endif # if ANDROID
endmenu
@@ -4,3 +4,4 @@ ccflags-y += -I$(src) # needed for trace events
obj-$(CONFIG_ANDROID_BINDERFS) += binderfs.o
obj-$(CONFIG_ANDROID_BINDER_IPC) += binder.o binder_alloc.o
obj-$(CONFIG_ANDROID_BINDER_IPC_SELFTEST) += binder_alloc_selftest.o
+obj-$(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING) += binder_latency_tracer.o
@@ -2674,6 +2674,7 @@ static void binder_transaction(struct binder_proc *proc,
return_error_line = __LINE__;
goto err_alloc_t_failed;
}
+ trace_binder_txn_latency_alloc(t);
INIT_LIST_HEAD(&t->fd_fixups);
binder_stats_created(BINDER_STAT_TRANSACTION);
spin_lock_init(&t->lock);
@@ -5177,6 +5178,7 @@ static void print_binder_transaction_ilocked(struct seq_file *m,
to_proc ? to_proc->pid : 0,
t->to_thread ? t->to_thread->pid : 0,
t->code, t->flags, t->priority, t->need_reply);
+ trace_binder_txn_latency_info(m, t);
spin_unlock(&t->lock);
if (proc != to_proc) {
@@ -5818,4 +5820,8 @@ static int __init binder_init(void)
#define CREATE_TRACE_POINTS
#include "binder_trace.h"
+EXPORT_TRACEPOINT_SYMBOL(binder_txn_latency_alloc);
+EXPORT_TRACEPOINT_SYMBOL(binder_txn_latency_info);
+EXPORT_TRACEPOINT_SYMBOL(binder_txn_latency_free);
+
MODULE_LICENSE("GPL v2");
@@ -15,6 +15,11 @@
#include <uapi/linux/android/binderfs.h>
#include "binder_alloc.h"
+#if IS_ENABLED(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING)
+#include <linux/rtc.h>
+#include <linux/time.h>
+#endif
+
struct binder_context {
struct binder_node *binder_context_mgr_node;
struct mutex context_mgr_node_lock;
@@ -524,6 +529,14 @@ struct binder_transaction {
* during thread teardown
*/
spinlock_t lock;
+ /**
+ * @ts and @real_ts are used to record the time
+ * that the binder transaction startup
+ */
+#if IS_ENABLED(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING)
+ struct timespec64 ts;
+ struct timespec64 real_ts;
+#endif
};
/**
new file mode 100644
@@ -0,0 +1,108 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2019 MediaTek Inc.
+ */
+
+#include <linux/module.h>
+#include <uapi/linux/android/binder.h>
+#include "binder_internal.h"
+#include "binder_trace.h"
+
+/**
+ * The reason setting the binder_txn_latency_threshold to 2 sec
+ * is that most of timeout abort is greater or equal to 2 sec.
+ * Making it configurable to let all users determine which
+ * threshold is more suitable.
+ */
+static uint32_t binder_txn_latency_threshold = 2;
+module_param_named(threshold, binder_txn_latency_threshold,
+ uint, 0644);
+
+/*
+ * probe_binder_txn_latency_free - Output info of a delay transaction
+ * @t: pointer to the over-time transaction
+ */
+void probe_binder_txn_latency_free(void *ignore, struct binder_transaction *t,
+ int from_proc, int from_thread,
+ int to_proc, int to_thread)
+{
+ struct rtc_time tm;
+ struct timespec64 *startime;
+ struct timespec64 cur, sub_t;
+
+ ktime_get_ts64(&cur);
+ startime = &t->ts;
+ sub_t = timespec64_sub(cur, *startime);
+
+ /* if transaction time is over than binder_txn_latency_threshold (sec),
+ * show timeout warning log.
+ */
+ if (sub_t.tv_sec < binder_txn_latency_threshold)
+ return;
+
+ rtc_time64_to_tm(t->real_ts.tv_sec, &tm);
+
+ pr_info_ratelimited("%d: from %d:%d to %d:%d",
+ t->debug_id, from_proc, from_thread,
+ to_proc, to_thread);
+
+ pr_info_ratelimited(" total %u.%03ld s code %u start %lu.%03ld android %d-%02d-%02d %02d:%02d:%02d.%03lu\n",
+ (unsigned int)sub_t.tv_sec,
+ (sub_t.tv_nsec / NSEC_PER_MSEC),
+ t->code,
+ (unsigned long)startime->tv_sec,
+ (startime->tv_nsec / NSEC_PER_MSEC),
+ (tm.tm_year + 1900), (tm.tm_mon + 1), tm.tm_mday,
+ tm.tm_hour, tm.tm_min, tm.tm_sec,
+ (unsigned long)(t->real_ts.tv_nsec / NSEC_PER_MSEC));
+}
+
+static void probe_binder_txn_latency_alloc(void *ignore,
+ struct binder_transaction *t)
+{
+ ktime_get_ts64(&t->ts);
+ ktime_get_real_ts64(&t->real_ts);
+ t->real_ts.tv_sec -= (sys_tz.tz_minuteswest * 60);
+}
+
+static void probe_binder_txn_latency_info(void *ignore, struct seq_file *m,
+ struct binder_transaction *t)
+{
+ struct rtc_time tm;
+
+ rtc_time64_to_tm(t->real_ts.tv_sec, &tm);
+ seq_printf(m,
+ " start %lu.%06lu android %d-%02d-%02d %02d:%02d:%02d.%03lu",
+ (unsigned long)t->ts.tv_sec,
+ (t->ts.tv_nsec / NSEC_PER_USEC),
+ (tm.tm_year + 1900), (tm.tm_mon + 1), tm.tm_mday,
+ tm.tm_hour, tm.tm_min, tm.tm_sec,
+ (unsigned long)(t->real_ts.tv_nsec / NSEC_PER_MSEC));
+}
+
+static int __init init_binder_latency_tracer(void)
+{
+ register_trace_binder_txn_latency_free(
+ probe_binder_txn_latency_free, NULL);
+ register_trace_binder_txn_latency_alloc(
+ probe_binder_txn_latency_alloc, NULL);
+ register_trace_binder_txn_latency_info(
+ probe_binder_txn_latency_info, NULL);
+
+ return 0;
+}
+
+static void exit_binder_latency_tracer(void)
+{
+ unregister_trace_binder_txn_latency_free(
+ probe_binder_txn_latency_free, NULL);
+ unregister_trace_binder_txn_latency_alloc(
+ probe_binder_txn_latency_alloc, NULL);
+ unregister_trace_binder_txn_latency_info(
+ probe_binder_txn_latency_info, NULL);
+}
+
+module_init(init_binder_latency_tracer);
+module_exit(exit_binder_latency_tracer);
+
+MODULE_LICENSE("GPL v2");
@@ -95,6 +95,17 @@
__entry->thread_todo)
);
+DECLARE_TRACE(binder_txn_latency_alloc,
+ TP_PROTO(struct binder_transaction *t),
+ TP_ARGS(t)
+);
+
+DECLARE_TRACE(binder_txn_latency_info,
+ TP_PROTO(struct seq_file *m,
+ struct binder_transaction *t),
+ TP_ARGS(m, t)
+);
+
TRACE_EVENT(binder_txn_latency_free,
TP_PROTO(struct binder_transaction *t,
int from_proc, int from_thread,
@@ -108,6 +119,8 @@
__field(int, to_thread)
__field(unsigned int, code)
__field(unsigned int, flags)
+ __field(unsigned long, start_sec)
+ __field(unsigned long, start_nsec)
),
TP_fast_assign(
__entry->debug_id = t->debug_id;
@@ -117,11 +130,18 @@
__entry->to_thread = to_thread;
__entry->code = t->code;
__entry->flags = t->flags;
- ),
- TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
+#if IS_ENABLED(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING)
+ __entry->start_sec = t->ts.tv_sec;
+ __entry->start_nsec = t->ts.tv_nsec / NSEC_PER_MSEC;
+#else
+ __entry->start_sec = 0;
+ __entry->start_nsec = 0;
+#endif
+ ),
+ TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x start %lu.%03ld",
__entry->debug_id, __entry->from_proc, __entry->from_thread,
__entry->to_proc, __entry->to_thread, __entry->code,
- __entry->flags)
+ __entry->flags, __entry->start_sec, __entry->start_nsec)
);
TRACE_EVENT(binder_transaction,