I have been playing with ftrace recently to monitor some behavior characteristics of my system. I've been handling switching the trace on/off via a small script. After running the script, my system would crash and reboot itself. Initially, I believed that there might be an error with the script itself, but I have since determined that the crash and reboot is a result of echoing some tracer to /sys/kernel/debug/tracing/current_tracer when current_tracer is set to function_graph.
That is, the following sequence of commands will produce the crash/reboot:
echo "function_graph" > /sys/kernel/debug/tracing/current_tracer
echo "function" > /sys/kernel/debug/tracing/current_tracer
Durning the reboot after the crash caused by the above echo statements, I see a lot of output that reads:
clearing orphaned inode
<inode>
I tried to reproduce this problem by replacing the current_tracer value from function_graph to something else in a C program:
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <string.h>
#include <stdlib.h>
int openCurrentTracer()
{
int fd = open("/sys/kernel/debug/tracing/current_tracer", O_WRONLY);
if(fd < 0)
exit(1);
return fd;
}
int writeTracer(int fd, char* tracer)
{
if(write(fd, tracer, strlen(tracer)) != strlen(tracer)) {
printf("Failure writing %s\n", tracer);
return 0;
}
return 1;
}
int main(int argc, char* argv[])
{
int fd = openCurrentTracer();
char* blockTracer = "blk";
if(!writeTracer(fd, blockTracer))
return 1;
close(fd);
fd = openCurrentTracer();
char* graphTracer = "function_graph";
if(!writeTracer(fd, graphTracer))
return 1;
close(fd);
printf("Preparing to fail!\n");
fd = openCurrentTracer();
if(!writeTracer(fd, blockTracer))
return 1;
close(fd);
return 0;
}
Oddly enough, the C program does not crash my system.
I originally encountered this problem while using Ubuntu (Unity environment) 16.04 LTS and confirmed it to be an issue on the 4.4.0 and 4.5.5 kernels. I have also tested this issue on a machine running Ubuntu (Mate environment) 15.10, on the 4.2.0 and 4.5.5 kernels, but was unable to reproduce the issue. This has only confused me further.
Can anyone give me insight on what is happening? Specifically, why would I be able to write() but not echo to /sys/kernel/debug/tracing/current_tracer?
Update
As vielmetti pointed out, others have had a similar issue (as seen here).
The
ftrace_disable_ftrace_graph_caller()modifies jmp instruction atftrace_graph_callassuming it's a 5 bytes near jmp (e9 ). However it's a short jmp consisting of 2 bytes only (eb ). Andftrace_stub()is located just below theftrace_graph_callerso modification above breaks the instruction resulting in kernel oops on theftrace_stub()with the invalid opcode like below:
The patch (shown below) solved the echo issue, but I still do not understand why echo was breaking previously when write() was not.
diff --git a/arch/x86/kernel/mcount_64.S b/arch/x86/kernel/mcount_64.S
index ed48a9f465f8..e13a695c3084 100644
--- a/arch/x86/kernel/mcount_64.S
+++ b/arch/x86/kernel/mcount_64.S
@@ -182,7 +182,8 @@ GLOBAL(ftrace_graph_call)
jmp ftrace_stub
#endif
-GLOBAL(ftrace_stub)
+/* This is weak to keep gas from relaxing the jumps */
+WEAK(ftrace_stub)
retq
END(ftrace_caller)
execcalls except possibly for the call todd)? Sometimes shells do funky stuff. – Mocambique/sys/kernel/debug/tracing/current_tracer. I say this because I can produce this problem without invoking the entire script, but instead by justechoing to that file. I listened to your suggestion with this in mind, and I have updated my post. – Leftwich