Linux Archive

Linux Archive (http://www.linux-archive.org/)
-   Debian ISP (http://www.linux-archive.org/debian-isp/)
-   -   Soft Lockups while running the daily cron job : what do with them (http://www.linux-archive.org/debian-isp/527268-soft-lockups-while-running-daily-cron-job-what-do-them.html)

Emmanuel Kasper 05-17-2011 09:33 AM

Soft Lockups while running the daily cron job : what do with them
 
Hello
On a relatively busy xen server, running 10 VM, I noticed soft lock
coming regularly, around 06:25.


kern.log.2.gz:May 2 06:27:15 vaduz kernel: [10156409.027744] INFO: task
dpkg-query:24275 blocked for more than 120 seconds.
kern.log.2.gz:May 4 06:27:13 vaduz kernel: [10329259.982553] INFO: task
locate:6752 blocked for more than 120 seconds.
syslog.6.gz:May 12 06:27:17 vaduz kernel: [11020672.410138] INFO: task
update-dlocated:9078 blocked for more than 120 seconds.
syslog.7.gz:May 11 06:27:22 vaduz kernel: [10934249.078237] INFO: task
dlocate:15949 blocked for more than 120 seconds.
syslog.7.gz:May 11 06:27:28 vaduz kernel: [10934255.518954] INFO: task
kjournald:1297 blocked for more than 120 seconds.
syslog.7.gz:May 11 06:27:45 vaduz kernel: [10934272.704136] INFO: task
pdflush:244 blocked for more than 120 seconds.

I guess every debian sysadmin around here will recognize the time at
which the daily crontab jobs :)

Am I right to think here that my server is simply starving for I/O ? I
am thinking of split cron jobs out between 5:00 and 7:00, would that be
the right thing to do ?

BTW if I understand right this kernel log is an INFO message, so it
means the kernel will not kill the process ? Or will he ?

MAnu

Carlos Alberto Lopez Perez 06-22-2011 01:44 PM

Soft Lockups while running the daily cron job : what do with them
 
On 05/17/2011 11:33 AM, Emmanuel Kasper wrote:
> Hello
> On a relatively busy xen server, running 10 VM, I noticed soft lock
> coming regularly, around 06:25.
>
>
> kern.log.2.gz:May 2 06:27:15 vaduz kernel: [10156409.027744] INFO: task
> dpkg-query:24275 blocked for more than 120 seconds.
> kern.log.2.gz:May 4 06:27:13 vaduz kernel: [10329259.982553] INFO: task
> locate:6752 blocked for more than 120 seconds.
> syslog.6.gz:May 12 06:27:17 vaduz kernel: [11020672.410138] INFO: task
> update-dlocated:9078 blocked for more than 120 seconds.
> syslog.7.gz:May 11 06:27:22 vaduz kernel: [10934249.078237] INFO: task
> dlocate:15949 blocked for more than 120 seconds.
> syslog.7.gz:May 11 06:27:28 vaduz kernel: [10934255.518954] INFO: task
> kjournald:1297 blocked for more than 120 seconds.
> syslog.7.gz:May 11 06:27:45 vaduz kernel: [10934272.704136] INFO: task
> pdflush:244 blocked for more than 120 seconds.
>
> I guess every debian sysadmin around here will recognize the time at
> which the daily crontab jobs :)
>
> Am I right to think here that my server is simply starving for I/O ? I
> am thinking of split cron jobs out between 5:00 and 7:00, would that be
> the right thing to do ?

A lot of people is suffering this bug and still is unknown where exactly is
the problem.

For me started to happen with the upgrade to Squeeze. I workarounded it
downgrading the kernel to lenny's one.


It will be very useful that you report it on the bugzilla's kernel.

The bug number is the following:

https://bugzilla.kernel.org/show_bug.cgi?id=18632

If you know how to reproduce it or when will it happen please do the
following when it is happening (as root)

echo t >/proc/sysrq-trigger

As a trick you can left the following dirty loop on a screen waiting for it
to happen:

while sleep 5; do dmesg |grep -q 'blocked for more than 120 seconds' &&
echo t >/proc/sysrq-trigger && break; done


And then a lot of info about the internal kernel status will be printed to
/var/log/kern.log

Upload that info with a brief description of what the system was doing when
it happened among useful information about your system like filesystems in
use, kind of cpu, modules loaded...

>
> BTW if I understand right this kernel log is an INFO message, so it
> means the kernel will not kill the process ? Or will he ?
>

No, the kernel will not kill anything. Only is letting you know that a
process was blocked for more than 120 seconds because the kernel was unable
to give the process the slot for I/O that it was requesting.


All times are GMT. The time now is 08:03 AM.

VBulletin, Copyright ©2000 - 2014, Jelsoft Enterprises Ltd.
Content Relevant URLs by vBSEO ©2007, Crawlability, Inc.