syslog(3) blocks when local socket is full - Unix

This is a discussion on syslog(3) blocks when local socket is full - Unix ; Hello everyone, My platform: Linux 2.6.22.1-rt9 + glibc 2.3.6 I'm writing a "real-time" application that runs with high priority (40 or 80 in SCHED_FIFO). I use syslog(3) to log. As far as I can see, syslog(3) blocks when the local ...

+ Reply to Thread
Results 1 to 6 of 6

Thread: syslog(3) blocks when local socket is full

  1. syslog(3) blocks when local socket is full

    Hello everyone,

    My platform: Linux 2.6.22.1-rt9 + glibc 2.3.6

    I'm writing a "real-time" application that runs with high priority
    (40 or 80 in SCHED_FIFO). I use syslog(3) to log.

    As far as I can see, syslog(3) blocks when the local socket becomes
    full (11 messages on my system).

    Consider the following program.

    #include
    int main(void)
    {
    int i;
    for (i=0; i < 500; ++i) syslog(LOG_INFO, "I=%d", i);
    return 0;
    }

    I kill syslogd, then start the above program. It blocks.
    I kill it, then start syslogd, which grabs the following messages.

    Nov 13 11:18:57 venus a.out: I=0
    Nov 13 11:18:57 venus a.out: I=1
    Nov 13 11:18:57 venus a.out: I=2
    Nov 13 11:18:57 venus a.out: I=3
    Nov 13 11:18:57 venus a.out: I=4
    Nov 13 11:18:57 venus a.out: I=5
    Nov 13 11:18:57 venus a.out: I=6
    Nov 13 11:18:57 venus a.out: I=7
    Nov 13 11:18:57 venus a.out: I=8
    Nov 13 11:18:57 venus a.out: I=9
    Nov 13 11:18:57 venus a.out: I=10

    (The process managed to write 11 messages before being blocked.)

    I expected a local socket to buffer way more than 11 messages.
    I expected a local socket to discard new messages when it is full.
    Apparently, these expectations are incorrect.

    I can see how this behavior can become a huge problem:

    Consider process A with prio 80 in SCHED_FIFO and process B with prio 10
    in SCHED_FIFO, i.e. process B only runs when A does not want the CPU.
    (syslogd is in SCHED_OTHER.)

    'A' runs, starts logging, and reaches the 11-message limit. The call to
    write() blocks, and 'A' is put to sleep. The scheduler then picks 'B'
    because it has higher priority than syslogd. If B runs "forever", 'A'
    will never get the CPU back.

    Is this scenario possible?

    Is this what is called priority inversion?

    Regards.

  2. Re: syslog(3) blocks when local socket is full

    Spoon writes:
    > I'm writing a "real-time" application that runs with high priority
    > (40 or 80 in SCHED_FIFO). I use syslog(3) to log.
    >
    > As far as I can see, syslog(3) blocks when the local socket becomes
    > full (11 messages on my system).


    [...]

    > I can see how this behavior can become a huge problem:
    >
    > Consider process A with prio 80 in SCHED_FIFO and process B with prio
    > 10 in SCHED_FIFO, i.e. process B only runs when A does not want the
    > CPU. (syslogd is in SCHED_OTHER.)
    >
    > 'A' runs, starts logging, and reaches the 11-message limit. The call
    > to write() blocks, and 'A' is put to sleep. The scheduler then picks
    > 'B' because it has higher priority than syslogd. If B runs "forever",
    > 'A' will never get the CPU back.
    >
    > Is this scenario possible?


    Yes.

    > Is this what is called priority inversion?


    Not quite, cf http://en.wikipedia.org/wiki/Priority_inversion. It's a
    fairly basic priorization error. If process A can only continue to
    work when process C (syslogd) actually executes when it becomes
    runnable, the priority of C should be higher than the priority of A.


  3. Re: syslog(3) blocks when local socket is full

    Rainer Weikusat wrote:

    > Spoon wrote:
    >
    >> I'm writing a "real-time" application that runs with high priority
    >> (40 or 80 in SCHED_FIFO). I use syslog(3) to log.
    >>
    >> As far as I can see, syslog(3) blocks when the local socket becomes
    >> full (11 messages on my system).

    >
    > [...]
    >
    >> I can see how this behavior can become a huge problem:
    >>
    >> Consider process A with prio 80 in SCHED_FIFO and process B with prio
    >> 10 in SCHED_FIFO, i.e. process B only runs when A does not want the
    >> CPU. (syslogd is in SCHED_OTHER.)
    >>
    >> 'A' runs, starts logging, and reaches the 11-message limit. The call
    >> to write() blocks, and 'A' is put to sleep. The scheduler then picks
    >> 'B' because it has higher priority than syslogd. If B runs "forever",
    >> 'A' will never get the CPU back.
    >>
    >> Is this scenario possible?

    >
    > Yes.
    >
    >> Is this what is called priority inversion?

    >
    > Not quite, cf http://en.wikipedia.org/wiki/Priority_inversion. It's a
    > fairly basic priorization error. If process A can only continue to
    > work when process C (syslogd) actually executes when it becomes
    > runnable, the priority of C should be higher than the priority of A.


    I see.

    The problem is that other processes write to /dev/log, therefore syslogd
    would sometimes run instead of the real-time process to read messages
    from unrelated and unimportant processes, which is unacceptable.

    The real-time process should run ASAP when it needs to run.

    I'm beginning to fear the solution is: "Don't use syslog."

  4. Re: syslog(3) blocks when local socket is full

    Spoon writes:
    > Rainer Weikusat wrote:
    >> Spoon wrote:
    >>
    >>> I'm writing a "real-time" application that runs with high priority
    >>> (40 or 80 in SCHED_FIFO). I use syslog(3) to log.
    >>>
    >>> As far as I can see, syslog(3) blocks when the local socket becomes
    >>> full (11 messages on my system).


    [...]

    >>> 'A' runs, starts logging, and reaches the 11-message limit. The call
    >>> to write() blocks, and 'A' is put to sleep. The scheduler then picks
    >>> 'B' because it has higher priority than syslogd. If B runs "forever",
    >>> 'A' will never get the CPU back.


    [...]

    >> If process A can only continue to work when process C (syslogd)
    >> actually executes when it becomes runnable, the priority of C
    >> should be higher than the priority of A.

    >
    > I see.
    >
    > The problem is that other processes write to /dev/log, therefore
    > syslogd would sometimes run instead of the real-time process to read
    > messages from unrelated and unimportant processes, which is
    > unacceptable.


    To the contrary, it is neccessary (when using syslog). Those other
    processes could otherwise fill the log buffer while A is not running,
    preventing A from running until it has been emptied again. This would
    be closer to a 'real' priority inversion.

    > The real-time process should run ASAP when it needs to run.
    > I'm beginning to fear the solution is: "Don't use syslog."


    This would probably be more sensible.

  5. Re: syslog(3) blocks when local socket is full

    On Tue, 13 Nov 2007 17:33:12 +0100, Spoon wrote:

    >Rainer Weikusat wrote:
    >
    >> Spoon wrote:
    >>> Is this what is called priority inversion?

    >>
    >> Not quite, cf http://en.wikipedia.org/wiki/Priority_inversion. It's a
    >> fairly basic priorization error. If process A can only continue to
    >> work when process C (syslogd) actually executes when it becomes
    >> runnable, the priority of C should be higher than the priority of A.

    >
    >I see.
    >
    >The problem is that other processes write to /dev/log, therefore syslogd
    >would sometimes run instead of the real-time process to read messages
    >from unrelated and unimportant processes, which is unacceptable.
    >
    >The real-time process should run ASAP when it needs to run.
    >
    >I'm beginning to fear the solution is: "Don't use syslog."


    So, am I right in thinking the summary of this is:

    "your high-priority real-time process may not use syslogd which is at
    a lower priority, IF there is any other process running with a
    priority higher than syslogd"?

    That makes a kind of intuitive sense to me, but then I Am Not A
    Real-Time Hacker!
    --
    PGP key ID 0xEB7180EC

  6. Re: syslog(3) blocks when local socket is full

    Keith Willis writes:
    > On Tue, 13 Nov 2007 17:33:12 +0100, Spoon wrote:
    >>Rainer Weikusat wrote:
    >>> Spoon wrote:
    >>>> Is this what is called priority inversion?
    >>>
    >>> Not quite, cf http://en.wikipedia.org/wiki/Priority_inversion. It's a
    >>> fairly basic priorization error. If process A can only continue to
    >>> work when process C (syslogd) actually executes when it becomes
    >>> runnable, the priority of C should be higher than the priority of A.

    >>
    >>I see.
    >>
    >>The problem is that other processes write to /dev/log, therefore syslogd
    >>would sometimes run instead of the real-time process to read messages
    >>from unrelated and unimportant processes, which is unacceptable.
    >>
    >>The real-time process should run ASAP when it needs to run.
    >>
    >>I'm beginning to fear the solution is: "Don't use syslog."

    >
    > So, am I right in thinking the summary of this is:
    >
    > "your high-priority real-time process may not use syslogd which is at
    > a lower priority, IF there is any other process running with a
    > priority higher than syslogd"?
    >
    > That makes a kind of intuitive sense to me,


    If the higher priority process can be prevented from running because a
    lower-priority process did not run, it is de facto of lower priority
    than the process which can prevent it from running. Assigning
    priorities in a way that does not reflect this will cause the assigned
    priorities to be ineffective in this particular situation.

+ Reply to Thread