6

I use syslog and rsyslog to handle logging on my Linux & FreeBSD systems.

The timestamp is currently in seconds but I would like to increase the precision of these timestamps to include milliseconds. Is this possible using the syslog variants such as rsyslog (RedHat, Ubuntu) or Syslog on FreeBSD?

If I did increase the logging timestamp to include microseconds, how accurate are these timestamps? If an event happened at 03:37:02:001 , does that mean that the event actually occurred at that exact millisecond, or is there a delay when syslog writes the event?

3 Answers 3

9

Most modern Syslog daemons (including rsyslog and syslog-ng) support high precision timestamping. If you're using one of these tools, you should have no difficulty configuring it.

As to it's accuracy. . . it depends. First of all, it's going to be dependent on the hardware. Most modern hardware supports high precision time, but not all. Assuming the hardware supports it, there's still a few challenges. Top priority will be making sure that your clock is set accurately, and that any other machines that are logging to it have matching time (assuming you're shipping logs from all your systems a central loghost). ntpd is the standard tool for maintaining accurate clock time (usually synced to the ntp.org pool).

Finally, we come to the event itself. The short answer is there will almost always be at least a little bit of drift, even if it is very slight. There is still going to be some variability here, too, depending on other factors. A lot will depend on where the event comes from, and how it gets picked up. For example, if I have an application that does foo, and then sends a log to syslog saying that the app did foo, it may take 100 ms between the completion of foo and sending the log. It may take another 20ms for the syslog() system call to complete.

I don't remember the low-level details of syslog, but I don't believe the event is timestamped when it is submitted to syslog, I think it is timestamped by the syslog daemon when it is picked up. That adds another few milliseconds to the mix.

Basically, unless you're dealing with a realtime system with realtime logging facilities, I don't think you'll ever get 100% perfect accuracy. Even then, you'd likely have (microscopic) levels of drift, but at least you'd have constraints to know your margin of error. At the same time, unless you have that level of requirement, your timestamp is probably going to be accurate enough.

3

Christopher covered the technical considerations: run ntpd, point it at a reliable source, and be cognizant of drift. I wanted to add a couple notes:

  • The timestamp is set by the syslog() libc function call. Here's uClibc's implementation. A typical syslog() invocation will complete in well under 1 ms. Here's the Ruby VM wrapping syslog() in 0.15 ms:

    Benchmark.measure { logger.info 'narf' }.real => 0.000149965286254883

  • While syslog may be suitable for millisecond precision, many Web app frameworks buffer logs and then either flush the buffer periodically or output all logs for a request after the request ends. Nearly all Web servers do the same (that's how the W3C common logfile format knows bytes transmitted). The impact is that millisecond precision is useful in fewer situations than it might seem.

  • Clock drift is endemic on VMs. From anecdotal mentions, 3 seconds per day is typical. Running ntpdate as a nightly cron job is not good enough.

  • Context usually makes order pretty obvious. If you haven't encountered a case where millisecond precision was the only way to know which event happened first, it's probably not worth the time.

0

In /etc/rsyslog.conf replace

$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat

by

$ActionFileDefaultTemplate RSYSLOG_FileFormat

And after restarting the service rsyslog, miliseconds will appears in log file

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .