printf in system call returns malformed output

Question

I'm logging system calls in OS X using a kext, like so:

int hook_read(struct proc *p, struct read_args *u, user_ssize_t *r) {
    /* get som params here... */
    printf("[IDEN] SYS_read called, %s, %d, %d, %d.\n", params);
    return read(p, u, r); 
}

This logs to system.log. The issue now is that if the printf load is high (many system calls are called), the output in system.log is often malformed: ID]SYS_readEN] callparam, 123, ed 123, 123 for example. The string is scrambled. If I use kprintf, which prints to a serial port, malformed logs never occur.

Any idea's what's causing this behaviour are much appreciated!

Answer 1

printf/IOLog uses a buffer for sending messages to userspace, where they're then logged to the system log. If you output a lot of messages, this buffer can get full before the logging daemon has a chance to clear it, and your messages will be truncated and start running into each other. (printf/IOLog will return as soon as the message has been submitted to the buffer, and will not wait for the daemon to receive it.)

Additionally, I'm not sure if kernel printf/IOLog is in any way thread-safe, so it might also be the case that calling it from multiple threads simultaneously causes race conditions. I'd have to check the source to be sure.

kprintf is fully synchronous and will block until your message has been transmitted on the serial port or submitted via firewire. It's also thread-safe. In the firewire case, the kprintf output is also buffered, so if you output a lot of messages, this can fill up too and cause truncation. The fwkpfv command lets you specify the buffer size using the --buffer argument though, so you can counteract that. The downside of kprintf being synchronous is that it can slow the system down considerably with a high volume of messages.