3

I am using printk in my kernel loadable module to log parameters of system calls. For each system call, several printks are used to print the variables whey they appear with "\t" as delimiters. To redirect the data in the kernel log buffer to another file other than system /var/log/messages, I use "klogd -f" to bypass the syslog interface. The log data obtained is one line per system call. However, after analyzing the data, I find that there exist 2 problems.

Problem 1: data may be lost.

Problem 2: data of one system call is mixed with data belonging to another system call, perhaps in the middle.

Question 1: is data loss caused by the kernel log buffer overflow which overwrites the oldest log in the buffer? If so, how to overcome it? I plan to increase the size of the kernel log buffer. Do you think it's appropriate and what size is best?

Question 2: can system call preempt another system call? Or in some situations, one system call may invoke another system call and can't finish unless the invoked one finishes? Is this the reason that the data get mixed with each other?

Question 3: is printk atomic? If not, how to make printk atomic? Add a lock to make it un-interruptable?

Steve Czetty
  • 6,147
  • 9
  • 39
  • 48
user1718039
  • 41
  • 2

1 Answers1

2

If you just want a dump of all of the system calls (with arguments) that a program is making, check out the strace command.

Question 1: Sort of. The kernel log buffer is implemented as a ring buffer. If the ring buffer is 128K and if the kernel writes a total of 129K worth of data since boot, the first 1K is overwritten by the newest data. You can increase the size of this buffer through the kernel boot argument log_buf_len or at compile time in your kernel's .config file. You can also change the size of the ring buffer with dmesg, by running dmesg -s524288 which will set it to 512KiB. You'll have to determine the best size depending on the amount of data you're spitting out.

Question 2: It's possible that one system call will preempt another system call, and there are plenty of other cases of preemption in the kernel -- interrupt service routines being a prime example. Also, if you're on a multi-core system, you could have more than one active kernel thread.

Question 3: I believe printk attempts to get a lock on the kernel's ring buffer. It's a bit complex though, since you can call printk from a panic state.

Ben Burns
  • 14,978
  • 4
  • 35
  • 56
  • Try holding your own debug buffer in your module and writing a system call to dump it, maybe? I'm not clear on your overall goal. If you're just logging system calls, check out the `strace` command. – Ben Burns Oct 04 '12 at 18:08
  • Hi, Ben. Thanks for your advice on strace command. However, strace requires the specific program to log known in advance, and what I need is a system-wide system call logging. That is, my overall goal is to intercept parameters of all system calls of all processes which have ever run on the system. Therefore, the log data will be "big data", which requires large buffer space and buffer content dumped promptly. – user1718039 Oct 05 '12 at 13:56
  • Eesh. Yeah, that's a complex problem. Can you virtualize your environment? If so, you might be able to utilize the debug environment in qemu in order to get this data. For instance, write a program that connects to qemu's debug server, throws breakpoints into the system calls you care about, and logs whatever data necessary when execution halts. You could also do this with a JTAG emulator if the machine you're working with allows it. http://www.cs.rochester.edu/users/faculty/sandhya/csc256/assignments/qemu_linux.html – Ben Burns Oct 05 '12 at 19:38
  • Either way, if you do come up with a solution, consider posting it on GitHub and letting the kernel devs know about it. They love crafty debug tools like this. – Ben Burns Oct 05 '12 at 19:39
  • Consider too that if you do this with any kind of userspace component in the same machine that you're logging data from, it'll most certainly cause additional system calls. In fact, it's probably not possible to do this with a userspace component unless it's smart enough to exclude its own calls - since eventually it'll just recursively clog itself with its own data. – Ben Burns Oct 05 '12 at 19:42
  • Nice point, Ben! I will look into qemu and JTAG. Thanks for advice. Also, please keep me updated when you come up with new thoughts. – user1718039 Oct 06 '12 at 18:02
  • dmesg -s does not change the size of the kernel ring buffer, only the buffer that dmesg uses to read from the ring buffer -- you have to use the kernel boot param to change the kernel ring buffer size – clemep Apr 12 '18 at 18:45