/ Zope / Apsis / Pound Mailing List / Archive / 2013 / 2013-08 / NULL: get_thr_arg spamming my syslog

[ << ] [ >> ]

[ [PATCH] HTTP PATCH Method - RFC5789 / Liam Fraser ... ] [ Disabled Fix / Joe Gooch <mrwizard(at)k12system... ]

NULL: get_thr_arg spamming my syslog
Brad Allison <brad.allison(at)gmail.com>
2013-08-27 21:45:39 [ FULL ]
My syslog is getting spammed by :

Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:37 pod01-lb-01 pound: NULL get_thr_arg

We just increased the pound threads from the default 128 to 500.

What does this error mean?

-brad
Attachments:  
text.html text/html 920 Bytes

Re: NULL: get_thr_arg spamming my syslog
Brad Allison <brad.allison(at)gmail.com>
2013-08-28 18:47:25 [ FULL ]
Any ideas?



On Tue, Aug 27, 2013 at 3:45 PM, Brad Allison
<brad.allison(at)gmail.com>wrote:
[...]
Attachments:  
text.html text/html 1345 Bytes

RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog
Joe Gooch <mrwizard(at)k12system.com>
2013-08-28 19:08:57 [ FULL ]
The thr_arg is a queue of requests. When running with a threadpool, each thread
reads from the thr_arg queue to determine the request it should process.  So
with 10 threads, 10 of them are stuck in a while loop, pulling thread
arguments.

The get_thr_arg function looks at the queue.  If it’s empty, it blocks waiting
for a signal.  (no error)
When a request comes in, it’s pushed onto the queue, and a signal is generated.
  One thread will wake up, grab the first item off the queue.  If there’s more
than one item left in the queue, another signal is generated. (to have another
thread pick up the next request)  Then what was popped off the top of the queue
is processed by the thread.

This error is generated when a thread wakes up, tries to process a request but
none is available.  In that case, it throws this warning, and goes back into
waiting status.  It’s either an indication that somewhere the conditional for
signaling a wakeup is possibly signaling too many wakeups, or that cond_wait is
prematurely waking up multiple threads.

If pound is functioning properly, these errors shouldn’t be a problem… as it
just goes back and starts waiting again.  (and you could comment the warning
out in http.c)  If it’s not, I’ll  need more information.


How often are you seeing these messages?
What OS are you running?
What version of pound are you using?
Were you getting these before increasing the default number of threads?


Joe

From: Brad Allison [mailto:brad.allison(at)gmail.com]
Sent: Wednesday, August 28, 2013 12:47 PM
To: pound(at)apsis.ch
Subject: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog

Any ideas?


On Tue, Aug 27, 2013 at 3:45 PM, Brad Allison
<brad.allison(at)gmail.com<mailto:brad.allison(at)gmail.com>>
wrote:
My syslog is getting spammed by :

Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:37 pod01-lb-01 pound: NULL get_thr_arg

We just increased the pound threads from the default 128 to 500.

What does this error mean?

-brad
Attachments:  
text.html text/html 7942 Bytes

RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog
Joe Gooch <mrwizard(at)k12system.com>
2013-08-28 19:54:14 [ FULL ]
Here’s what I see… someone with more pthread experience may want to chime in. 
V2.6 code.

Each thread does this:

get_thr_arg(void)
{
    thr_arg *res;

    (void)pthread_mutex_lock(&arg_mut);
    if(first == NULL)
        (void)pthread_cond_wait(&arg_cond, &arg_mut);
    if((res = first) != NULL)
        if((first = first->next) == NULL)
            last = NULL;
    (void)pthread_mutex_unlock(&arg_mut);
   if(first != NULL)
        pthread_cond_signal(&arg_cond);
    return res;
}

Basically:
Lock
  If queue empty, block on condition
  Pop from top
Unlock
  Signal on condition if queue non-empty
  Return data


Each time a new socket request comes in , pthread_cond_signal is called… Which,
intuitively, would mean 5 incoming requests = 5 woken up threads = 5 processed
requests.  Plus once a thread’s awake, if it finishes its task, it might end up
grabbing another request anyway. (if that happens, one of the threads woken up
will throw a NULL warning)  The additional cond_signal in get_thr_arg seems to
be just that, additional and extra.

The warning in the log indicates a thread woke up but had no data.

The problem I have is all the soft wording in the pthread docs:
“The pthread_cond_signal() call unblocks at least one of the threads”
“Spurious wakeups from the pthread_cond_wait() or pthread_cond_timedwait()
functions may occur”


There doesn’t seem to be any guarantee that 5 pthread_cond_signal() calls = 5
threads waking up.  Nor is there any guarantee that pthread_cond_signal() won’t
wake up 5 threads instead of 1.

When I take out the extra call at the end of get_thr_arg, everything still runs
perfectly fine, and I don’t have get_thr_arg NULL warnings anymore.  That
indicates to me that on Linux, on my environment, pthreads is doing 1 signal =
1 wakeup, and the extra call is unnecessary.  But given all the soft language
in the manual I’m not comfortable removing the extra signal, as it might be
there for a reason, and/or to deal with other pthread implementations.

Code smell indicates to me that if the last signal is to stick around, the last
first != NULL should instead be res!=NULL && res->next!=NULL… as we
shouldn’t be accessing “first” outside of our mutex.
I would further guess that given the pthread manual soft language, the warning
should just be commented out or set to a less severe log message level, rather
than removing the extra signal.

Comments welcome.

Joe

From: Joe Gooch [mailto:mrwizard(at)k12system.com]
Sent: Wednesday, August 28, 2013 1:09 PM
To: 'pound(at)apsis.ch'
Subject: RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog

The thr_arg is a queue of requests. When running with a threadpool, each thread
reads from the thr_arg queue to determine the request it should process.  So
with 10 threads, 10 of them are stuck in a while loop, pulling thread
arguments.

The get_thr_arg function looks at the queue.  If it’s empty, it blocks waiting
for a signal.  (no error)
When a request comes in, it’s pushed onto the queue, and a signal is generated.
  One thread will wake up, grab the first item off the queue.  If there’s more
than one item left in the queue, another signal is generated. (to have another
thread pick up the next request)  Then what was popped off the top of the queue
is processed by the thread.

This error is generated when a thread wakes up, tries to process a request but
none is available.  In that case, it throws this warning, and goes back into
waiting status.  It’s either an indication that somewhere the conditional for
signaling a wakeup is possibly signaling too many wakeups, or that cond_wait is
prematurely waking up multiple threads.

If pound is functioning properly, these errors shouldn’t be a problem… as it
just goes back and starts waiting again.  (and you could comment the warning
out in http.c)  If it’s not, I’ll  need more information.


How often are you seeing these messages?
What OS are you running?
What version of pound are you using?
Were you getting these before increasing the default number of threads?


Joe

From: Brad Allison [mailto:brad.allison(at)gmail.com]
Sent: Wednesday, August 28, 2013 12:47 PM
To: pound(at)apsis.ch
Subject: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog

Any ideas?


On Tue, Aug 27, 2013 at 3:45 PM, Brad Allison
<brad.allison(at)gmail.com<mailto:brad.allison(at)gmail.com>>
wrote:
My syslog is getting spammed by :

Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:36 pod01-lb-01 pound: NULL get_thr_arg
Aug 27 19:44:37 pod01-lb-01 pound: NULL get_thr_arg

We just increased the pound threads from the default 128 to 500.

What does this error mean?

-brad
Attachments:  
text.html text/html 17283 Bytes

RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog
"jacob anderson" <jwa(at)beyond-ordinary.com>
2013-08-28 20:44:22 [ FULL ]
I like to refer to IBM's docs on pthreads when looking up this stuff:

 

http://publib.boulder.ibm.com/infocenter/iseries/v5r4/index.jsp?topic=%2Fapis%2Fusers_78.htm

 

I think you should change the first " if(first == NULL) " to " while(first ==
NULL) " . 

 

My very humble and lacking-any-code-context-opinion.

 
[...]
Attachments:  
text.html text/html 20808 Bytes

RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog
Joe Gooch <mrwizard(at)k12system.com>
2013-08-28 23:50:19 [ FULL ]
Then every thread would fully empty the queue.  Each thread needs to grab one
request only. (and leave the rest for the next thread)

Joe

From: jacob anderson [mailto:jwa(at)beyond-ordinary.com]
Sent: Wednesday, August 28, 2013 2:44 PM
To: pound(at)apsis.ch
Subject: RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog

I like to refer to IBM’s docs on pthreads when looking up this stuff:

http://publib.boulder.ibm.com/infocenter/iseries/v5r4/index.jsp?topic=%2Fapis%2Fusers_78.htm

I think you should change the first “ if(first == NULL) “ to “ while(first ==
NULL) “ …

My very humble and lacking-any-code-context-opinion.
[...]
Attachments:  
text.html text/html 22212 Bytes

RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog
"jacob anderson" <jwa(at)beyond-ordinary.com>
2013-08-29 00:05:03 [ FULL ]
if(first == NULL)

        (void)pthread_cond_wait(&arg_cond, &arg_mut);

 

->

  while(first == NULL) 

        (void)pthread_cond_wait(&arg_cond, &arg_mut);

 

This says "while there is no item in the list, you wait Mr. Thread"

 

Then when one "first" is not null, a thread gets the mutex and pulls the first
item. The other threads would wait, AND
the spurious thread that awakens by mistake would wait for the mutex, get it,
see first=null, and then go to sleep.

 

Maybe I am misunderstanding the semantics of pthread_cond_wait .

 
[...]
Attachments:  
text.html text/html 25768 Bytes

RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog
Joe Gooch <mrwizard(at)k12system.com>
2013-08-29 15:48:57 [ FULL ]
IC now. Yes. I like that solution.  I can’t imagine a case where we’d get to
the end of the function and res would be NULL in that case.

Joe

From: jacob anderson [mailto:jwa(at)beyond-ordinary.com]
Sent: Wednesday, August 28, 2013 6:05 PM
To: pound(at)apsis.ch
Subject: RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog

    if(first == NULL)
        (void)pthread_cond_wait(&arg_cond, &arg_mut);

->
  while(first == NULL)
        (void)pthread_cond_wait(&arg_cond, &arg_mut);

This says “while there is no item in the list, you wait Mr. Thread”

Then when one “first” is not null, a thread gets the mutex and pulls the first
item. The other threads would wait, AND the spurious thread that awakens by
mistake would wait for the mutex, get it, see first=null, and then go to sleep.

Maybe I am misunderstanding the semantics of pthread_cond_wait …
[...]
Attachments:  
text.html text/html 27144 Bytes

RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog
Joe Gooch <mrwizard(at)k12system.com>
2013-08-30 16:14:44 [ FULL ]
Implemented.

Joe

From: Joe Gooch [mailto:mrwizard(at)k12system.com]
Sent: Thursday, August 29, 2013 9:49 AM
To: 'pound(at)apsis.ch'
Subject: RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog

IC now. Yes. I like that solution.  I can’t imagine a case where we’d get to
the end of the function and res would be NULL in that case.

Joe

From: jacob anderson [mailto:jwa(at)beyond-ordinary.com]
Sent: Wednesday, August 28, 2013 6:05 PM
To: pound(at)apsis.ch<mailto:pound(at)apsis.ch>
Subject: RE: [Pound Mailing List] Re: NULL: get_thr_arg spamming my syslog

    if(first == NULL)
        (void)pthread_cond_wait(&arg_cond, &arg_mut);

->
  while(first == NULL)
        (void)pthread_cond_wait(&arg_cond, &arg_mut);

This says “while there is no item in the list, you wait Mr. Thread”

Then when one “first” is not null, a thread gets the mutex and pulls the first
item. The other threads would wait, AND the spurious thread that awakens by
mistake would wait for the mutex, get it, see first=null, and then go to sleep.

Maybe I am misunderstanding the semantics of pthread_cond_wait …
[...]
Attachments:  
text.html text/html 28568 Bytes

MailBoxer